After upgrade to 7.1 logging has stopped working

[sbeaver]

I have done the upgrade to 7.1 on a few nodes and after the upgrade has completed none of the System.log or Server.log calls are not writing anything to the screen.  Anyone got any idea what could be missing to get the logging back?

Thanks

Steve

[iiliev]

There is a known issue with DEBUG messages logged using System.debug(...) - see release notes http://pubs.vmware.com/Release_Notes/en/orchestrator/vrealize-orchestrator-71-release-notes.html

Could you check if the other logging levels work or not - System.error(...), System.warn(...), System.debug(...)

Also, could you check if the messages you log with System.error(...), System.warn(...), System.debug(...) and System.log(...) appear in the log file /var/log/vco/app-server/scripting.log ?

[sbeaver]

I added the change recommended in the KB but alas still nothing is showing up in any of the logs from the client and I created a workflow just to do the different logging and that was not showing up in the scripting log although I see output from other workflows but something that I log

[iiliev]

Hmm, the fact that messages are missing from scripting.log file explains why you don't see anything in the client log pane.

The strange thing is why some workflows are able to log successfully and others cannot. Weird.

[mbrkic]

Hi,

did you ever sort this out? I just upgraded to 7.1 and I am having the same issue with the client not displaying logs at all.

I see the logs in scripting.log on the server, they just don't show up in the Logs pane.

If you have an answer it would be much appreciated.

Cheers,

Milos

[iiliev]

Hi Milos,

Just to clarify - in scripting.log file you see log messages logged with various log levels using System.log()/System.debug()/System.warn()/System.error() but in the client you don't see any message at any log level, right?

I think this could happen if there is a big time skew between vRO server and client machines. Could you check if this is the case in your environment?

BTW, is your client started via JNLP, or is it an installed/standalone application client?

[mbrkic]

Thanks for your response.

I have seen the comments about time difference in other posts and that should not be an issue:

And yes, I am using the Java client downloaded from the Orchestrator main web page, not the installed client, although I have tried it with the installed client as well with same results.

Cheers,

Milos

[iiliev]

Hmm, I'm running out of ideas. Just a couple more things to check:

1) Check for possible clues in vRO log files (at /var/log/vco/app-server/) and vRO client log file (vso.log, usually created in the same directory where the JNLP file is).

2) To avoid possibility for corrupted log index, you can delete the folder /var/log/vco/app-server/scripting.log_lucene/ and restart vRO server with service vro-server restart.

[mbrkic]

Thanks for the tips.

1. Nothing jumps out in the logs - there is a large number of them on the server side. I tried grepping for a few things, looking at the warnings.log etc. No clear clues.
2. This folder does not exist. As a matter of fact there are no files on the server with 'lucene' in the name other than a bunch of jar files.

Cheers,

Milos

[iiliev]

Interesting. This means for some reason Lucene indexing is not working. Lucene is used in logs' indexing/processing logic so the indexing service is expected to be working for proper access to logs from client applications.

There is a small chance that enabling Log4j debug logs will dump some messages related to Lucene startup issues. Could you add the following lines to /etc/vco/app-server/vmo.properties and restart vco-server service?

  log4j.debug=true

  log4j.configDebug=true

After service is restarted, check logs under /var/log/vco/app-server/, especially catalina.out, for messages starting with/containing log4j

Another possibility is also something to be broken after the upgrade to 7.1. Could you verify if you have the same issue if you deploy a clean 7.1 installation? If logging works on the clean 7.1 installation, could you try to diff folders /etc/vco/app-server/ and /usr/lib/vco/ on clean and upgraded installations to check what are differences?

[mbrkic]

I figured out what the issue was.

I had previously changed the log4j.xml to keep a larger number of scripting.log files. This made the upgrader not overwrite this config file. Instead it created a log4j.xml.rpmnew file with the new config. There are a lot of changes and updates to this file, which made the lucene part not work at all.

I replaced my log4j.xml with the new one and all is well - the client is logging again!

Thanks for the pointers to get me on the right track with this. I would give you the points, but I am not the OP.

Cheers,

Milos

[sbeaver]

I ended up copying the file from a system that was logging properly.  Here is a copy of what was working in my environment and that I copied and pasted into the rest of my nodes.

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

　

  <!-- ================================= -->

  <!-- Server log -->

  <!-- ================================= -->

  <appender class="org.productivity.java.syslog4j.impl.log4j.Syslog4jAppender" name="LOGINSIGHT">

  <param name="Threshold" value="INFO"/>

  <param name="Facility" value="LOCAL1"/>

  <param name="Protocol" value="tcp"/>

  <param name="Host" value="vlog.insight.com"/>

  <param name="Port" value="514"/>

  <param name="maxMessageLength" value="128000"/>

  <layout class="org.apache.log4j.PatternLayout">

  <param name="ConversionPattern" value="vco: ${com.vmware.o11n.server.instanceid} prio:%-5p thread:%t context:%X{context} token:%X{token} anctoken:%X{anctoken} wf:%X{workflowName} wfid:%X{workflow} user: %X{username} cat:%c{1} msg:%m%n"/>

  </layout>

</appender><appender class="org.apache.log4j.RollingFileAppender" name="FILE">

  <param name="File" value="${catalina.base}/logs/server.log"/>

  <param name="Append" value="true"/>

  <param name="Encoding" value="UTF-8"/>

　

  <!-- Rollover at 5MB and allow 4 rollover files -->

  <param name="MaxFileSize" value="5MB"/>

  <param name="MaxBackupIndex" value="4"/>

　

  <layout class="org.apache.log4j.PatternLayout">

  <!-- The default pattern: Date Priority [Category] Message\n -->

  <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSSZ} [%t] %-5p {%X{full}} [%c{1}] %m%n"/>

  </layout>

  </appender>

  <!-- ================================= -->

  <!-- Server log used by Log Insight Agent -->

  <!-- ================================= -->

  <appender class="org.apache.log4j.RollingFileAppender" name="FILE_INTEGRATION">

  <param name="File" value="${catalina.base}/logs/integration-server.log"/>

  <param name="Append" value="true"/>

  <param name="Encoding" value="UTF-8"/>

　

  <!-- Rollover at 5MB -->

  <param name="MaxFileSize" value="5MB"/>

  <param name="MaxBackupIndex" value="1"/>

　

  <layout class="org.apache.log4j.PatternLayout">

  <!-- The default pattern: Date Priority [Category] Message\n -->

  <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSSZ} vco: [component=&quot;%c{1}&quot; priority=&quot;%p&quot; thread=&quot;%t&quot; user=&quot;%X{user}&quot; context=&quot;%X{context}&quot; token=&quot;%X{token}&quot; wfid=&quot;%X{workflow}&quot; wfname=&quot;%X{workflowName}&quot; anctoken=&quot;%X{anctoken}&quot; wfstack=&quot;%X{workflowStack}&quot; instanceid=&quot;${com.vmware.o11n.server.instanceid}&quot;] %m%n"/>

  </layout>

  </appender>

  <!-- ================================= -->

  <!-- Metrics log used by Log Insight Agent and Control Center -->

  <!-- ================================= -->

  <appender class="org.apache.log4j.RollingFileAppender" name="METRICS">

  <param name="File" value="${catalina.base}/logs/metrics.log"/>

  <param name="Append" value="true"/>

  <param name="Encoding" value="UTF-8"/>

　

  <!-- Rollover at 5MB and allow 4 rollover files -->

  <param name="MaxFileSize" value="5120KB"/>

  <param name="MaxBackupIndex" value="4"/>

　

  <layout class="org.apache.log4j.PatternLayout">

  <!-- The default pattern: Date Priority [Category] Message\n -->

  <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSSZ} %m%n"/>

  </layout>

  </appender>

  <appender class="org.apache.log4j.RollingFileAppender" name="VC-METRICS">

  <param name="File" value="${catalina.base}/logs/vc-metrics.log"/>

  <param name="Append" value="true"/>

  <param name="Encoding" value="UTF-8"/>

　

  <!-- Rollover at 5MB and allow 4 rollover files -->

  <param name="MaxFileSize" value="5120KB"/>

  <param name="MaxBackupIndex" value="4"/>

　

  <layout class="org.apache.log4j.PatternLayout">

  <!-- The default pattern: Date Priority [Category] Message\n -->

  <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSSZ} %m%n"/>

  </layout>

  </appender>

  <!-- ================================= -->

  <!-- Warning log -->

  <!-- ================================= -->

  <appender class="org.apache.log4j.RollingFileAppender" name="WARNING_LOGS">

  <param name="File" value="${catalina.base}/logs/warning.log"/>

  <param name="Append" value="true"/>

  <param name="Encoding" value="UTF-8"/>

　

  <!-- Rollover at 5MB and allow 4 rollover files -->

  <param name="MaxFileSize" value="5120KB"/>

  <param name="MaxBackupIndex" value="4"/>

　

  <layout class="org.apache.log4j.PatternLayout">

  <!-- The default pattern: Date Priority [Category] Message\n -->

  <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSSZ} [%t] %-5p {%X{full}} [%c{1}] %m%n"/>

  </layout>

  </appender>

　

  <!-- ================================= -->

  <!-- Scripting log -->

  <!-- ================================= -->

  <appender class="com.vmware.o11n.service.logging.RollingLogFileAppender" name="SCRIPT_LOGS">

  <param name="File" value="${catalina.base}/logs/scripting.log"/>

  <param name="Append" value="true"/>

  <param name="Encoding" value="UTF-8"/>

　

  <!-- Rollover at 20MB and allow 5 rollover files -->

  <param name="MaxFileSize" value="20480KB"/>

  <param name="MaxBackupIndex" value="5"/>

　

  <layout class="org.apache.log4j.PatternLayout">

  <!-- The default pattern: Date Priority [Category] Message\n -->

  <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSSZ} %-5p {%X{username}:%X{token}%X{tokenctx}} [%c{1}] %m%n"/>

  </layout>

  </appender>

  <!-- ================================= -->

  <!-- Scripting log used by Log Insight Agent -->

  <!-- ================================= -->

  <appender class="org.apache.log4j.RollingFileAppender" name="SCRIPT_INTEGRATION">

  <param name="File" value="${catalina.base}/logs/integration-scripting.log"/>

  <param name="Append" value="true"/>

  <param name="Encoding" value="UTF-8"/>

　

  <!-- Rollover at 10MB -->

  <param name="MaxFileSize" value="10240KB"/>

  <param name="MaxBackupIndex" value="1"/>

　

  <layout class="org.apache.log4j.PatternLayout">

  <!-- The default pattern: Date Priority [Category] Message\n -->

  <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSSZ} vco: [component=&quot;%c{1}&quot; priority=&quot;%p&quot; thread=&quot;%t&quot; user=&quot;%X{user}&quot; context=&quot;%X{context}&quot; token=&quot;%X{token}&quot; wfid=&quot;%X{workflow}&quot; wfname=&quot;%X{workflowName}&quot; anctoken=&quot;%X{anctoken}&quot; wfstack=&quot;%X{workflowStack}&quot; instanceid=&quot;${com.vmware.o11n.server.instanceid}&quot;] %m%n"/>

  </layout>

  </appender>

　

  <!-- ============================== -->

  <!-- Append messages to the console -->

  <!-- ============================== -->

  <appender class="org.apache.log4j.ConsoleAppender" name="CONSOLE">

  <param name="Target" value="System.out"/>

  <param name="Encoding" value="UTF-8"/>

　

  <layout class="org.apache.log4j.PatternLayout">

  <!-- The default pattern: Date Priority [Category] Message\n -->

  <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSSZ} [%t] %-5p {%X{full}} [%c{1}] %m%n"/>

  </layout>

  </appender>

　

  <!-- ============================== -->

  <!-- Append messages to the syslogd -->

  <!-- ============================== -->

  <!--

  <appender name="SYSLOG" class="org.apache.log4j.net.SyslogAppender">

  <param name="Facility" value="<<FACILITY>>"/>

  <param name="SyslogHost" value="<<HOST>>"/>

  <param name="FacilityPrinting" value="true"/>

  <param name="maxMessageLength" value="128000"/>

  <layout class="org.apache.log4j.PatternLayout">

  <param name="ConversionPattern" value="vCO:${com.vmware.o11n.server.instanceid} prio:%-5p thread:%t token:%X{token} wf:%X{workflowName} wfid:%X{workflow} user: %X{username} cat:%c{1} msg:%m%n"/>

  </layout>

  </appender>

  -->

　

  <!-- ============================== -->

  <!-- Append messages to the Windows Event Log -->

  <!-- ============================== -->

  <!--

  <appender name="EVENT_LOG" class="org.apache.log4j.nt.NTEventLogAppender">

  <param name="Source" value="vCO"/>

  <layout class="org.apache.log4j.PatternLayout">

  <param name="ConversionPattern" value="[%t] {%X{full}} [%c{1}] %m%n"/>

  </layout>

  </appender>

  -->

　

  <!-- Control Center log stream -->

  <appender class="org.apache.log4j.net.SocketAppender" name="SOCKET">

  <param name="Port" value="8238"/>

  <param name="RemoteHost" value="localhost"/>

  <param name="ReconnectionDelay" value="5000"/>

  <param name="LocationInfo" value="false"/>

  </appender>

　

  <!-- vRO warning log -->

  <category additivity="false" name="IGNORED_EXCEPTION">

  <priority value="WARN"/>

  <appender-ref ref="WARNING_LOGS"/>

  </category>

　

  <!-- vRO metrics log -->

  <category additivity="false" name="metrics">

  <priority value="INFO"/>

  <appender-ref ref="METRICS"/>

  </category>

  <!-- vCenter plugin Metrics log -->

  <category additivity="false" name="vc-metrics">

  <priority value="INFO"/>

  <appender-ref ref="VC-METRICS"/>

  </category>

　

  <!-- vRO logs -->

  <category additivity="true" name="ch.dunes">

  <priority value="INFO"/>

  </category>

  <category additivity="true" name="com.vmware.o11n">

  <priority value="INFO"/>

  </category>

  <category additivity="true" name="Execution">

  <priority value="INFO"/>

  </category>

　

  <category additivity="true" name="com.vmware.vim.sso.client">

  <priority value="ERROR"/>

  </category>

  <category additivity="true" name="com.vmware.vim.vmomi.core.types">

  <priority value="ERROR"/>

  </category>

　

  <!-- VMware Infrastructure plugins -->

  <category additivity="true" name="com.vmware.vmo.plugin.vi35">

  <priority value="INFO"/>

  </category>

  <category additivity="true" name="com.vmware.vmo.plugin.vi4">

  <priority value="INFO"/>

  </category>

　

  <category additivity="true" name="org.springframework">

  <priority value="INFO"/>

  </category>

  <!-- Remove the 'Bound to JNDI name' log info -->

  <category additivity="true" name="org.hornetq">

  <priority value="INFO"/>

  </category>

  <!-- Limit the org.hibernate category to WARN as its INFO is verbose -->

  <category additivity="true" name="org.hibernate">

  <priority value="WARN"/>

  </category>

  <category additivity="true" name="org.hibernate.cfg.SettingsFactory">

  <priority value="ERROR"/>

  </category>

  <category additivity="true" name="org.apache.http">

  <priority value="INFO"/>

  </category>

  <category additivity="true" name="org.apache.directory">

  <priority value="FATAL"/>

  </category>

  <category additivity="true" name="net.sf.ehcache">

  <priority value="INFO"/>

  </category>

  <category additivity="false" name="org.apache.tomcat.jdbc.pool.ConnectionPool">

  <priority value=""/>

  </category>

　

  <!-- Scripting log -->

  <category additivity="false" name="SCRIPTING_LOG">

  <priority value="INFO"/>

  <appender-ref ref="FILE"/>

  <appender-ref ref="FILE_INTEGRATION"/>

  <appender-ref ref="SCRIPT_LOGS"/>

  <appender-ref ref="SCRIPT_INTEGRATION"/>

  <appender-ref ref="SOCKET"/>

　

  <!--

  <appender-ref ref="SYSLOG" />

  -->

  <!--

  <appender-ref ref="EVENT_LOG" />

  -->

  <appender-ref ref="LOGINSIGHT" />

  </category>

　

  <!-- Default root category -->

  <root>

  <priority value="INFO"/>

  <appender-ref ref="FILE"/>

  <appender-ref ref="FILE_INTEGRATION"/>

  <appender-ref ref="SOCKET"/>

  <!--

  <appender-ref ref="SYSLOG" />

  -->

  <!--

  <appender-ref ref="EVENT_LOG" />

  -->

  <appender-ref ref="LOGINSIGHT" />

  </root>

</log4j:configuration>

[sbeaver]

FYI in the example I posted above I am using Log Insight.  You may not be in your environment

[iiliev]

OK, so we'll probably need to prepare a KB article for this issue, documenting how it can be resolved manually after upgrade.