Cisco WebEx Social Troubleshooting Guide, Release 3.4 and 3.4 SR1 - Logs [Cisco WebEx Social]

Most Cisco WebEx Social logs are centralized on the Director node. There are a few exceptions (log files with dynamic name patterns and non-critical logs) where log files are managed localy on nodes instead of streaming to the Director node.

Cisco WebEx Social uses rsyslog as a logging framework. rsyslog sends critical logs to the Director node but, if configured, can also stream logs to an upstream host (see the Cisco WebEx Social Administration Guide for details).

The central log location on the Director node is /opt/logs/<date>/ where date is the date that the log message was written. For example /opt/logs/2012_12_01/ would contain all log messages generated on Dec 1 2012.

The logs on the Director can be accessed through the Director GUI (see the Cisco WebEx Social Administration Guide for details) or through the Cisco WebEx Social Director API.

Log Files Stored on the Director by Role

This sections lists the log files that each role sends to the Director.

Table 4-1 Log Files Stored on the Director
Role	Log filename
Director	%HOSTNAME%_director_web.log %HOSTNAME%_catalina.log %HOSTNAME%_localhost.log %HOSTNAME%_manager.log %HOSTNAME%_host_manager.log %HOSTNAME%_deploy_db.log %HOSTNAME%_graphite_access.log %HOSTNAME%_graphite_exception.log %HOSTNAME%_graphite_info.log %HOSTNAME%_graphite_error.log %HOSTNAME%_carbon_console.log %HOSTNAME%_salt_master.log %HOSTNAME%_mongod.log %HOSTNAME%_jsonstore.log %HOSTNAME%_analyticsstore.log
App Server	%HOSTNAME%_appserver.log %HOSTNAME%_analyticsmrscheduler.log %HOSTNAME%_catalina.log %HOSTNAME%_localhost.log %HOSTNAME%_tomcat-access.log %HOSTNAME%_manager.log %HOSTNAME%_host_manager.log %HOSTNAME%_httpd_access.log %HOSTNAME%_httpd_error.log %HOSTNAME%_cmanager.log %HOSTNAME%_cmanager_debug.log %HOSTNAME%_cmanager_info.log %HOSTNAME%_cmanager_warn.log %HOSTNAME%_cmanager_error.log %HOSTNAME%_deploy_db.log %HOSTNAME%_audit.log
Worker	%HOSTNAME%_worker.log %HOSTNAME%_catalina.log %HOSTNAME%_localhost.log %HOSTNAME%_manager.log %HOSTNAME%_host_manager.log %HOSTNAME%_httpd_access.log %HOSTNAME%_httpd_error.log %HOSTNAME%_cmanager.log %HOSTNAME%_cmanager_debug.log %HOSTNAME%_cmanager_info.log %HOSTNAME%_cmanager_warn.log %HOSTNAME%_cmanager_error.log
Message Queue	%HOSTNAME%_message-queue_wrapper.log %HOSTNAME%_message-queue.log %HOSTNAME%_message-queue_shutdown_err %HOSTNAME%_message-queue_startup_err %HOSTNAME%_message-queue_shutdown.log %HOSTNAME%_message-queue_startup.log %HOSTNAME%_rabbitmq.log %HOSTNAME%_rabbitmq-sasl.log
Notifier	%HOSTNAME%_notifier.log %HOSTNAME%_notifier_nohup.out %HOSTNAME%_notifier_debug.log %HOSTNAME%_notifier_info.log %HOSTNAME%_notifier_warn.log %HOSTNAME%_notifier_error.log
Cache	%HOSTNAME%_messages
Search Store	%HOSTNAME%_search.log %HOSTNAME%_search.request.log
Index Store	%HOSTNAME%_index.log %HOSTNAME%_index.request.log
Analytics Store	%HOSTNAME%_mongod.log
JSON Store	%HOSTNAME%_mongod.log
RDBMS Store	%HOSTNAME%_oracle_quad_log.xml %HOSTNAME%_oracle_alert_quad.log %HOSTNAME%_oracle_rdfprod_log.xml %HOSTNAME%_oracle_alert_rdfprod.log %HOSTNAME%_oracle_sqlnet.log
Common logs (all roles)	%HOSTNAME%_secure %HOSTNAME%_mail_log %HOSTNAME%_cron %HOSTNAME%_spooler %HOSTNAME%_boot.log %HOSTNAME%_collectd.log %HOSTNAME%_monit.log %HOSTNAME%_puppet.log %HOSTNAME%_messages %HOSTNAME%_nagios.log %HOSTNAME%_faillog %HOSTNAME%_lastlog %HOSTNAME%_snmpd.log %HOSTNAME%_yum.log %HOSTNAME%_tallylog %HOSTNAME%_vmware_tools_guestd %HOSTNAME%_wtmp %HOSTNAME%_audit_local_log %HOSTNAME%_mail_statistics %HOSTNAME%_pm-suspend.log %HOSTNAME%_prelink.log %HOSTNAME%_mod-jk.log %HOSTNAME%_rewrite.log %HOSTNAME%_ssl_access_log %HOSTNAME%_ssl_request_log %HOSTNAME%_ssl_error_log %HOSTNAME%_install.log %HOSTNAME%_install.log.syslog %HOSTNAME%_salt_minion.log

Localy-stored Log Files by Role

This sections lists the log files that some roles store localy.

Table 4-2 Localy-stored Log Files
Role	Log filename
RDBMS Store	/opt/oracle/app/oracle/diag/rdbms/[quad, rdfprod]/[quad, rdfprod]/cdump/* /opt/oracle/app/oracle/admin/[quad, rdfprod]/adump/* /opt/oracle/app/oracle/diag/tnslsnr//listener/alert/log.xml /opt/oracle/app/oracle/diag/tnslsnr//listener/trace/listener.log /opt/oracle/app/oracle/diag/rdbms/[quad,rdfprod]/[quad, rdfprod]/trace/.trc,.trm
Common logs (all roles)	/var/log/sa/sa* /var/log/httpd/[ssllog] /var/log/anaconda. /var/log/btmp /var/log/dmesg /var/log/dracut.log

Understanding Logs

This section contains log excerpts for variuos normal and abnormal events, as follows:

•Monit Logs

•Resource Overutilization

•Purging /opt

•Nagios Starts Up/Shuts Down

•Common False Positives

•Failure: Core Service is Down for an Extended Period of Time

•Rsyslog Starts Up/Shuts Down

•Rsyslog is Rate Limited

•Service is Down

•Analytics Service Initialized Successfully

•MapReduce Scheduler Logs

•Calendar Logs

•Framework Logs

•Streams Logs

•Email Integration Logs

•Office Plug-in Logs

•Cisco WebEx Social Call Plug-in Logs

•WebEx Social for Office Logs

•Open API Logs

•Click to Call and Click to Chat Logs

•Email Notifications About Announcements and Alerts

•Synthetic Monitor

•Centralized Credentials Management (Master Password)

•Session Centralization

Monit Logs

This section is organized as follows:

•Monit Starts Up

•Monit Check Failed

•Manually Restarting Monit

Monit Starts Up

These log entries are generated during normal monit startup.

Mar 15 20:40:35 quad-web-a monit[19684]: Shutting down monit HTTP server

Mar 15 20:40:35 quad-web-a monit[19684]: monit HTTP server stopped

Mar 15 20:40:35 quad-web-a monit[19684]: monit daemon with pid [19684] killed

Mar 15 20:40:35 quad-web-a monit[19684]: 'system_quad-web-a.example.com' Monit stopped

Mar 15 20:40:35 quad-web-a monit[27469]: Starting monit daemon with http interface at 
[*:2812]

Mar 15 20:40:35 quad-web-a monit[27469]: Monit start delay set -- pause for 120s

Mar 15 20:42:35 quad-web-a monit[27472]: Starting monit HTTP server at [*:2812]

Mar 15 20:42:35 quad-web-a monit[27472]: monit HTTP server started

Mar 15 20:42:35 quad-web-a monit[27472]: 'system_quad-web-a.example.com' Monit started

Monit Check Failed

These log entries are generated when collectd and httpd are not running and are failing to start:

Mar 15 21:05:27 quad-web-b monit[16949]: 'collectd' process is not running

Mar 15 21:05:27 quad-web-b monit[16949]: 'collectd' trying to restart

Mar 15 21:05:27 quad-web-b monit[16949]: 'collectd' start: /etc/init.d/collectd

Mar 15 20:17:27 quad-web-a monit[19684]: 'httpd' process is not running

Mar 15 20:17:27 quad-web-a monit[19684]: 'httpd' trying to restart

Mar 15 20:17:27 quad-web-a monit[19684]: 'httpd' start: /etc/init.d/httpd

Mar 15 20:17:57 quad-web-a monit[19684]: 'httpd' failed to start

Manually Restarting Monit

These log entries are generated when a service is restarted manually in which case monit detects the PID change and logs it:

May 22 18:02:13 quad-web-c monit[1811]: 'rsyslog' process PID changed from 1425 to 2959

May 22 18:03:13 quad-web-c monit[1811]: 'rsyslog' process PID has not changed since last 
cycle

Resource Overutilization

These log entries are generated when monit has detected that a resource utilization has gone over the prefedined threshold:

May 27 18:25:11 quad-web-a monit[2236]: 'rsyslog' cpu usage of 50.1% matches resource 
limit [cpu usage>50.0%]

Purging /opt

These log entries are generated when monit has detected that the /opt usage has grown beynd 85% and the purge action has been performed:

Jun  5 01:05:44 quad-test monit[16057]: 'opt' space usage 92.6% matches resource limit 
[space usage>85.0%]

Jun  5 01:05:44 quad-test monit[16057]: 'opt' exec: /bin/bash

Jun  5 01:05:44 quad-test monit: /opt disk usage exceeded 85% threshold. Purging log 
folder: /opt/logs/2012_06_03

These log entries are generated when "today" is the only remaining folder and there is nothing left to purge:

Jun  5 01:07:44 quad-test monit: /opt disk usage exceeded 85% threshold. Purging log 
folder:

Nagios Starts Up/Shuts Down

These log entries are generated during normal Nagios startup/shutdown.

[1336003714] Nagios 3.3.1 starting... (PID=9416)

[1336003714] Local time is Thu May 03 00:08:34 UTC 2012

[1336003714] LOG VERSION: 2.0

[1336003714] Finished daemonizing... (New PID=9417)

....................

[1335307549] Auto-save of retention data completed successfully.

[1336003770] Caught SIGTERM, shutting down...

[1336003770] Successfully shutdown... (PID=9417)

Common False Positives

These false positives are known to appear:

•Node is No Longer Active/Available but Exists in the Topology

•Monit service Not Running on a Node

•Chart Data Missing for a Node

Node is No Longer Active/Available but Exists in the Topology

[1335313142] SERVICE ALERT: test.example.com;Load: 
midterm;UNKNOWN;HARD;4;check_graphite_stats :err : getData failed 500

[1335296859] SERVICE ALERT: test.example.com;Disk: opt;CRITICAL;SOFT;1;CRITICAL: 
Exception: [Errno 113] No route to host

Monit service Not Running on a Node

Node name in the example: test.example.com.

[1335946047] SERVICE NOTIFICATION: 
nagiosadmin;test.example.com;cron;CRITICAL;notify-service-by-email;CRITICAL: Exception: 
[Errno 111] Connection refused

Chart Data Missing for a Node

The charts are fed by collectd. If you are missing data for a particular node, look for the collectd log on the Director for that node.

In many cases the counters are either 0 or missing for certain attributes on certain nodes. For example, with ActiveMQ, there is only one active node at any one time. The other node is in standby mode waiting to take over. The resulting log messages look like this for the standby AMQ node:

May 29 16:00:09 quad-queue-2 collectd[3793]: GenericJMXConfValue.query: Querying attribute 
TotalEnqueueCount failed.

May 29 16:00:09 quad-queue-2 collectd[3793]: GenericJMXConfValue.query: getAttribute 
failed: javax.management.RuntimeMBeanException: java.lang.NullPointerException

This is normal behavior in this case as the other AMQ node is currently active.

Failure: Core Service is Down for an Extended Period of Time

These log entries are generated when a core service has not been running for an extended period of time.

[1335317564] SERVICE ALERT: quad-test.example.com;ntpd;CRITICAL;SOFT;1;CRITICAL: PROCESS 
ntpd: failed to start

[1335317624] SERVICE ALERT: quad-test.example.com;ntpd;CRITICAL;SOFT;2;CRITICAL: PROCESS 
ntpd: failed to start

[1335317684] SERVICE ALERT: quad-test.example.com;ntpd;CRITICAL;SOFT;3;CRITICAL: PROCESS 
ntpd: failed to start

[1335317744] SERVICE ALERT: quad-test.example.com;ntpd;CRITICAL;HARD;4;CRITICAL: PROCESS 
ntpd: failed to start

[1335317744] SERVICE NOTIFICATION: 
test@example.com;quad-test.example.com;ntpd;CRITICAL;notify-service-by-email;CRITICAL: 
PROCESS ntpd: failed to start

[1335318044] SERVICE ALERT: quad-test.example.com;ntpd;OK;HARD;4;OK: Total 1 services are 
monitored

[1335318044] SERVICE NOTIFICATION: 
test@example.com;quad-test.example.com;ntpd;OK;notify-service-by-email;OK: Total 1 
services are monitored

The text highlighted in red shows that:

•There have been four successive failures, which causes Nagios to generate an email alert.

•The email address that the alert was sent to (test@example.com).

•The text that was sent in the email (the rest of the message).

The very last line shows:

•The service recovering (indicated by the OK: Total 1 services are monitored).

•The email address that the alert was sent to (test@example.com) informing the service has gone back online.

Rsyslog Starts Up/Shuts Down

These log entries are generated during normal rsyslog startup/shutdown.

May 31 01:22:16 quad-web-a kernel: Kernel logging (proc) stopped.

May 31 01:22:16 quad-web-a rsyslogd: [origin software="rsyslogd" swVersion="5.8.6" 
x-pid="1612" x-info="http://www.rsyslog.com"] exiting on signal 15.

May 31 01:22:17 quad-web-a kernel: imklog 5.8.6, log source = /proc/kmsg started.

May 31 01:22:17 quad-web-a rsyslogd: [origin software="rsyslogd" swVersion="5.8.6" 
x-pid="28666" x-info="http://www.rsyslog.com"] start

Rsyslog is Rate Limited

These log entries are generated when rsyslog has reached the default maximum of 200 input log messages per 5 seconds. Any excess messages are dropped for the process.

May 25 23:37:36 quad-web-a rsyslogd-2177: imuxsock begins to drop messages from pid 2061 
due to rate-limiting

May 25 23:40:02 quad-web-a rsyslogd-2177: imuxsock lost 1085 messages from pid 2061 due to 
rate-limiting

Service is Down

If a service is down, collectd won't be able to collect stats for that service, for example if the Worker service is not running then the Health state manager check fails and collectd logs the following:

Jun  4 21:01:44 quad-web-b collectd[7176]: curl_json plugin: curl_easy_perform failed with 
status 7: couldn't connect to host (http://localhost:8080/monit/status.do?output=json)

If Memcached is not running, you see a message like this:

Jun  7 00:04:24 quad-cache-1 collectd[6847]: memcached: Could not connect to daemon.

Analytics Service Initialized Successfully

This log message appears if the Analytics service on an App Server or Worker node initializes successfully.

AnalyticEventReceiver initialized

MapReduce Scheduler Logs

Mapreduce jobs are run for analytics and suggestions. Typically, these jobs are run once per day (unless you change the "Analytics Store Cron Job Hour of Day (UTC)" on the Director, in which case the scheduler job might run again for the day when it was changed).

The mapreduce scheduler logs are writen to worker-host-name_analyticsmrscheduler.log. One of the Worker nodes picks up the entire job for execution.

•To verify the job has started, look for:

Running Map Reduce Jobs

•The end of the job is signified by this message:

-------  MapReduce Jobs completed. Exiting Program  -----------------

•To see if all mapreduce jobs completed successfully, run:

cat worker-host-name_analyticsmrscheduler.log | grep 'exitValue'

The command should return something similar to:

Apr 26 00:00:08 ecp-10-194-190-32.example.com analyticsmrscheduler[]: INFO  
[ANALYTICS_MR_SCHEDULER] - [pool-32-thread-2]: Process : cmd = user_library_usage, 
exitValue = 0

An exitValue = 0 signifies that the command has executed successfully. If any command has an exitValue not equal to 0, there is likely some issue executing the mapreduce jobs.

•If you see messages similar to "login failed", check for the following:

Execute:

/usr/bin/mongo -u username -p password analytics_store_host:port/dbName /opt/cisco/scheduler/analytics/mapreduce/user_library_usage.js

Verify that username, analytics_store_host, port, and dbName match the respective properties set in portal-ext.properties. If they match, ensure that the credentials are valid for the quadanalytics database on the Analytics Store.

If the credentials look good, but the login still fails, there might be no primary Analytics Store node on the cluster; all available nodes might be in secondary mode. Check if that is the case by running:

db.isMaster();

inside the mongo console on each Analytics Store node.

•If you see that there are no scheduler logs being generated, go to the Director > Configuration and check the running schedule (it is set to run at midnight GMT by default). If the schedule run has passed, check if the MessageQueue Scheduler Queue has some messages stuck. If you see the messages are stuck, check if the Worker role shows exceptions. If there are no exceptions, ensure Message Queue is working properly.

Calendar Logs

This section explains the following procedures from logging standpoint:

•Getting a Month Worth of Meetings with Configured Domino and WebEx (No Cached Data)

•Getting a Month Worth of Meetings with Configured Domino and WebEx (Cached Data)

•Getting a Month Worth of Meetings with Configured WebDAV (No Cached Data)

•Selecting a Domino Event from the List of Events

Getting a Month Worth of Meetings with Configured Domino and WebEx (No Cached Data)

When you click on the arrow to go to the next month in the Calendar application (assuming that this is the first time you request the data—that is, there is no data in the cache), the application goes through the following steps, logging the respective messages:

Step 1 Display the Domino settings that are used to connect to Domino.

DEBUG 14:07:40,269 | AGGREGATED_CALENDAR:65 | [   ] Using Domino Calendar settings for 
user: "r3". Username: "vmdomino domino", Password: "****", URL: "198.51.100.35", Domain: 
"dominotest"

Step 2 Try to get the events for Domino from the cache without success.

INFO  14:07:40,279 | AGGREGATED_CALENDAR:78 | [   ] getCachedListEvents:[AggCalCacheUtil]: 
Cache miss for [Mail-Chain-10195-14610005_Sat Mar 31 21:00:00 GMT 2012_Sat May 05 20:59:59 
GMT 2012] - we got 0 meetings

Step 3 Try to get the events for WebEx from the cache without success.

INFO  14:07:40,279 | AGGREGATED_CALENDAR:78 | [   ] getCachedListEvents:[AggCalCacheUtil]: 
Cache miss for [WebEx-Chain-10195-14610005_Sat Mar 31 21:00:00 GMT 2012_Sat May 05 
20:59:59 GMT 2012] - we got 0 meetings

Step 4 Display the period for which the events are being retrieved from Domino.

INFO  14:07:40,279 | AGGREGATED_CALENDAR:78 | [   ] Get events from Sat Mar 31 21:00:00 
GMT 2012 to Sat May 05 20:59:59 GMT 2012

Step 5 Display the period for which the events are being retrieved from WebEx.

INFO  14:07:40,281 | AGGREGATED_CALENDAR:78 | [   ] Get events from Sat Mar 31 21:00:00 
GMT 2012 to Sat May 05 20:59:59 GMT 2012

Step 6 Successful creation of a Domino session.

INFO  14:07:40,289 | AGGREGATED_CALENDAR:78 | [   ] Domino session was successfully 
created for user: vmdomino domino

Step 7 Execute a query to get the events from Domino.

DEBUG 14:07:40,293 | AGGREGATED_CALENDAR:65 | [   ] SELECT 
((@IsAvailable(CalendarDateTime) & (@Explode(CalendarDateTime) *= 
@Explode(@TextToTime("04/01/2012 12:00:00 AM ZE2-05/05/2012 11:59:59 PM ZE2")))) | 
(@IsAvailable(EndDateTime) & (@Explode(EndDateTime) *= @Explode(@TextToTime("04/01/2012 
12:00:00 AM ZE2-05/05/2012 11:59:59 PM ZE2")))) & @IsUnavailable(FailureReason) & 
(@IsAvailable(AppointmentType) & AppointmentType <> "1" & AppointmentType <> "4") & (Form 
= "Appointment"))

Step 8 Parse each Domino meeting attendees by common name (CN).

DEBUG 14:07:40,376 | AGGREGATED_CALENDAR:65 | [   ] Search user document for common name: 
CN=gp gp

DEBUG 14:07:40,386 | AGGREGATED_CALENDAR:65 | [   ] Search user document for common name: 
CN=r2@example.com

DEBUG 14:07:40,388 | AGGREGATED_CALENDAR:65 | [   ] Search user document for common name: 
CN=vmdomino domino

Step 9 Output each Domino meeting after we have processed it.

TRACE 14:07:40,397 | AGGREGATED_CALENDAR:53 | [   ] Events:

[eventId : 594B9C51FA2258CCC22579AC00431138 - 1335862800000 - 1335872700000

subject : Domino - host

    location :

    organizer :

    email : vmdomino @ dominotest.com

    screenName : vmdomino

    fullName : vmdomino domino

    attendees : [

        email : gp @ dominotest.com

        screenName : ggp

        fullName : gp gp,

        email : r2 @ example.com

        screenName :

        fullame : r2 @ example.com]

    nonSendableTo : null

    required : null

    resource : null

    htmlDescription : null

    hasattachment : false

    importance : null

    allDayEvent : false

    reminderOffset : null

    href : null

    busyStatus : BUSY

    textDescription : THis is some rich text

    Lets see what goes to the client

    startDate : Tue May 01 09 : 00 : 00 GMT 2012

    endDate : Tue May 01 11 : 45 : 00 GMT 2012

    isRecurring : false

    recurrencePattern : null

    hasPartialMeetingData : false

    webExDetails : {

        null

Step 10 Cache asynchronously the list of received Domino events.

DEBUG 14:37:41,408 | AGGREGATED_CALENDAR:65 | [   ] cacheListEvents:[AggCalCacheUtil]: 
[26] meetings cached for [Mail-Chain-10195-14610005_Sat Mar 31 21:00:00 GMT 2012_Sat May 
05 20:59:59 GMT 2012]

Step 11 Cache asynchronously each Domino event.

DEBUG 14:37:41,410 | AGGREGATED_CALENDAR:65 | [   ] cacheMeeting:[AggCalCacheUtil]: 
Meeting cached for 
[DCAED24B00328A37C22579B90057D567-1333375200000-1333378800000-10195-14610005]

DEBUG 14:37:41,410 | AGGREGATED_CALENDAR:65 | [   ] cacheMeeting:[AggCalCacheUtil]: 
Meeting cached for 
[0DE08C580301255FC22579DC002A8062-1334066400000-1334070000000-10195-14610005]

DEBUG 14:37:41,410 | AGGREGATED_CALENDAR:65 | [   ] cacheMeeting:[AggCalCacheUtil]: 
Meeting cached for 
[E371DB4510E56367C22579DC002E5EA8-1334133900000-1334134800000-10195-14610005]

DEBUG 14:37:41,411 | AGGREGATED_CALENDAR:65 | [   ] cacheMeeting:[AggCalCacheUtil]: 
Meeting cached for 
[2426637EABDBD784C22579DC002C3108-1334140200000-1334143800000-10195-14610005]

DEBUG 14:37:41,411 | AGGREGATED_CALENDAR:65 | [   ] cacheMeeting:[AggCalCacheUtil]: 
Meeting cached for 
[4D3E6229EF5DCA07C22579DC002D2EEF-1334483100000-1334484000000-10195-14610005]

...

Step 12 Cache asynchronously the list of received WebEx events.

DEBUG 14:37:44,377 | AGGREGATED_CALENDAR:65 | [   ] cacheListEvents:[AggCalCacheUtil]: 
[20] meetings cached for [WebEx-Chain-10195-14610005_Sat Mar 31 21:00:00 GMT 2012_Sat May 
05 20:59:59 GMT 2012]

Getting a Month Worth of Meetings with Configured Domino and WebEx (Cached Data)

When you click on the arrow to go to the next month in the Calendar application (assuming that this is not the first time you request the data—that is, there is data in the cache), the application logs the following messages:

INFO  12:50:05,479 | AGGREGATED_CALENDAR:78 | [   ] getCachedListEvents:[AggCalCacheUtil]: 
Cache hit for [WebEx-Chain-10195-14610005_Sat Mar 31 21:00:00 GMT 2012_Sat May 05 20:59:59 
GMT 2012] - we got 20 meetings

INFO  12:50:05,479 | AGGREGATED_CALENDAR:78 | [   ] getCachedListEvents:[AggCalCacheUtil]: 
Cache hit for [Mail-Chain-10195-14610005_Sat Mar 31 21:00:00 GMT 2012_Sat May 05 20:59:59 
GMT 2012] - we got 26 meetings

Getting a Month Worth of Meetings with Configured WebDAV (No Cached Data)

When you click on the arrow to go to the next month in the Calendar application (assuming this that is the first time you request the data—that is, there is no data in the cache), the application goes through the following steps, logging the respective messages:

Step 1 Display the Exchange settings that are used to connect to Exchange.

DEBUG 13:52:37,382 | AGGREGATED_CALENDAR:65 | [   ] Using Exchange Calendar settings for 
user: "r2". Username: "vm2007", Password: "****", URL: 
"https://198.51.100.35/exchange/vm2007/", Domain: ""

Step 2 Try to get the events for Exchange from the cache without success.

INFO  13:52:37,385 | AGGREGATED_CALENDAR:78 | [   ] getCachedListEvents:[AggCalCacheUtil]: 
Cache miss for [Mail-Chain-10195-1410026_Sun Mar 25 21:00:00 GMT 2012_Sun May 06 20:59:59 
GMT 2012] - we got 0 meetings

Step 3 Execute a WebDAV query to log into WebDAV.

DEBUG 13:52:37,421 | AGGREGATED_CALENDAR:65 | [   ] Search Query:

<?xml version='1.0'?><d:searchrequest xmlns:d="DAV:"><d:sql>SELECT 
"urn:schemas:httpmail:subject", 
"urn:schemas:calendar:location","urn:schemas:mailheader:to", 
"urn:schemas:mailheader:cc","http://schemas.microsoft.com/mapi/nonsendableto","urn:schemas
:mailheader:from","urn:schemas:calendar:organizer", 
"urn:schemas:calendar:uid","urn:schemas:calendar:instancetype", 
"urn:schemas:httpmail:htmldescription", "urn:schemas:httpmail:hasattachment", 
"urn:schemas:calendar:busystatus", "urn:schemas:httpmail:textdescription", 
"urn:schemas:calendar:alldayevent", "urn:schemas:calendar:reminderoffset", 
"urn:schemas:calendar:dtstart","urn:schemas:calendar:dtend", 
"urn:schemas:calendar:created", "urn:schemas:calendar:recurrenceid", 
"urn:schemas:calendar:lastmodified"  FROM Scope('SHALLOW TRAVERSAL OF 
"https://198.51.100.35/exchange/vm2007/calendar"') WHERE NOT 
"urn:schemas:calendar:instancetype" = 1 AND "urn:schemas:calendar:dtend" &lt;= 
CAST("2012-04-27T13:52:37.421Z" as 'dateTime') AND  "urn:schemas:calendar:dtstart" &gt;= 
CAST("2012-04-26T13:52:37.421Z" as 'dateTime')  ORDER BY "urn:schemas:calendar:dtstart" 
ASC </d:sql></d:searchrequest>

Step 4 Get the response.

INFO  13:52:37,440 | AGGREGATED_CALENDAR:78 | [   ] Number of events we got: 0

TRACE 13:52:37,441 | AGGREGATED_CALENDAR:53 | [   ] Response Document: <?xml version="1.0" 
encoding="UTF-16"?><a:multistatus xmlns:a="DAV:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" xmlns:c="xml:" 
xmlns:d="urn:schemas:httpmail:" xmlns:e="urn:schemas:calendar:" 
xmlns:f="urn:schemas:mailheader:" xmlns:g="http://schemas.microsoft.com/mapi/"/>

Step 5 Execute another WebDav query to get the events for the month.

DEBUG 13:52:37,441 | AGGREGATED_CALENDAR:65 | [   ] login exchange server sucessful

DEBUG 13:52:37,442 | AGGREGATED_CALENDAR:65 | [   ] resolveMailServerInfo(() success code: 
200

DEBUG 13:52:37,442 | AGGREGATED_CALENDAR:65 | [   ] Search Query:

<?xml version='1.0'?><d:searchrequest xmlns:d="DAV:"><d:sql>SELECT 
"urn:schemas:httpmail:subject", 
"urn:schemas:calendar:location","urn:schemas:mailheader:to", 
"urn:schemas:mailheader:cc","http://schemas.microsoft.com/mapi/nonsendableto", 
"urn:schemas:mailheader:from", "urn:schemas:calendar:organizer", 
"urn:schemas:calendar:uid","urn:schemas:calendar:instancetype", 
"urn:schemas:httpmail:htmldescription", "urn:schemas:httpmail:hasattachment", 
"urn:schemas:calendar:busystatus","urn:schemas:httpmail:textdescription", 
"urn:schemas:calendar:alldayevent","urn:schemas:calendar:reminderoffset", 
"urn:schemas:calendar:dtstart","urn:schemas:calendar:dtend", 
"urn:schemas:calendar:created", "urn:schemas:calendar:recurrenceid", 
"urn:schemas:calendar:lastmodified"  FROM Scope('SHALLOW TRAVERSAL OF 
"https://198.51.100.35/exchange/vm2007/calendar"') WHERE NOT 
"urn:schemas:calendar:instancetype" = 1 AND "urn:schemas:calendar:dtend" &lt;= 
CAST("2012-05-06T20:59:59.999Z" as 'dateTime') AND  "urn:schemas:calendar:dtstart" &gt;= 
CAST("2012-03-25T21:00:00.000Z" as 'dateTime')  ORDER BY "urn:schemas:calendar:dtstart" 
ASC </d:sql></d:searchrequest>

Step 6 Get the response.

INFO  13:52:37,466 | AGGREGATED_CALENDAR:78 | [   ] Number of events we got: 7

TRACE 13:52:37,475 | AGGREGATED_CALENDAR:53 | [   ] Response Document: <?xml version="1.0" 
encoding="UTF-16"?><a:multistatus xmlns:a="DAV:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" xmlns:c="xml:" 
xmlns:d="urn:schemas:httpmail:" xmlns:e="urn:schemas:calendar:" 
xmlns:f="urn:schemas:mailheader:" xmlns:g="http://schemas.microsoft.com/mapi/">

   <a:response>

      <a:href>https://198.51.100.35/exchange/vm2007/Calendar/Have%20fun-5.EML</a:href>

      <a:propstat>

         <a:status>HTTP/1.1 200 OK</a:status>

         <a:prop>

            <d:subject>Have fun</d:subject>

            <e:location>some location</e:location>  <e:uid> 
040000008200E00074C5B7101A82E008000000006C327C3319FDCC010000000000000000100000003AD41318CF
A170488967581FBBC63202 </e:uid>            <e:instancetype b:dt="int">3</e:instancetype>

            <d:htmldescription>&lt;!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2//EN"&gt;

&lt;HTML&gt;

&lt;HEAD&gt;

&lt;META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=utf-8"&gt;

&lt;META NAME="Generator" CONTENT="MS Exchange Server version 08.03.0083.000"&gt;

&lt;TITLE&gt;Have fun&lt;/TITLE&gt;

&lt;/HEAD&gt;

&lt;BODY&gt;

&lt;!-- Converted from text/plain format --&gt;&lt;P&gt;&lt;FONT SIZE=2&gt;When: 
Wednesday, March 28, 2012 3:00 AM-4:00 AM. (GMT-08:00) Pacific Time (US &amp;amp; 
Canada)&lt;BR&gt;

Where: some location&lt;BR&gt;

&lt;BR&gt;

*~*~*~*~*~*~*~*~*~*&lt;BR&gt;

&lt;BR&gt;

&amp;nbsp;some body here&lt;BR&gt;&lt;/FONT&gt;

&lt;/P&gt;

&lt;/BODY&gt;

&lt;/HTML&gt;</d:htmldescription>

            <d:hasattachment b:dt="boolean">0</d:hasattachment>

            <e:busystatus>TENTATIVE</e:busystatus>

            <d:textdescription>When: Wednesday, March 28, 2012 3:00 AM-4:00 AM. 
(GMT-08:00) Pacific Time (US &amp; Canada)

Where: some location

*~*~*~*~*~*~*~*~*~*

some body here

</d:textdescription>

            <e:alldayevent b:dt="boolean">0</e:alldayevent>

            <e:reminderoffset b:dt="int">900</e:reminderoffset>

            <e:dtstart b:dt="dateTime.tz">2012-03-28T10:00:00.000Z</e:dtstart>

            <e:dtend b:dt="dateTime.tz">2012-03-28T11:00:00.000Z</e:dtend>

            <e:created b:dt="dateTime.tz">2012-03-08T10:49:58.000Z</e:created>

            <e:recurrenceid b:dt="dateTime.tz">2012-03-11T10:00:00.000Z</e:recurrenceid>

            <e:lastmodified b:dt="dateTime.tz">2012-04-10T14:29:08.000Z</e:lastmodified>

         </a:prop>

      </a:propstat>

      <a:propstat>

         <a:status>HTTP/1.1 404 Resource Not Found</a:status>

         <a:prop>

            <f:to/>

            <f:cc/>

            <g:nonsendableto/>

            <f:from/>

            <e:organizer/>

         </a:prop>

      </a:propstat>

   </a:response>

...

</a:multistatus>

Step 7 Receive a warning because there is a meeting without an organizer.

WARN  13:52:37,505 | AGGREGATED_CALENDAR:90 | [   ] Failed to get organizer for WebDav 
event [Have fun] with ID 
[040000008200E00074C5B7101A82E008000000006C327C3319FDCC010000000000000000100000003AD41318C
FA170488967581FBBC63202@2012-03-11T10:00:00.000Z]

DEBUG 13:52:37,508 | AGGREGATED_CALENDAR:65 | [   ] <?xml version="1.0" 
encoding="UTF-16"?><a:response xmlns:a="DAV:">

   <a:href>https://198.51.100.35/exchange/vm2007/Calendar/Have%20fun-5.EML</a:href>

   <a:propstat>

      <a:status>HTTP/1.1 200 OK</a:status>

      <a:prop>

         <d:subject xmlns:d="urn:schemas:httpmail:">Have fun</d:subject>

         <e:location xmlns:e="urn:schemas:calendar:">some location</e:location>

         <e:uid xmlns:e="urn:schemas:calendar:"> 
040000008200E00074C5B7101A82E008000000006C327C3319FDCC010000000000000000100000003AD41318CF
A170488967581FBBC63202 </e:uid>

         <e:instancetype xmlns:e="urn:schemas:calendar:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" b:dt="int">3</e:instancetype>

         <d:htmldescription xmlns:d="urn:schemas:httpmail:">&lt;!DOCTYPE HTML PUBLIC 
"-//W3C//DTD HTML 3.2//EN"&gt;

&lt;HTML&gt;

&lt;HEAD&gt;

&lt;META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=utf-8"&gt;

&lt;META NAME="Generator" CONTENT="MS Exchange Server version 08.03.0083.000"&gt;

&lt;TITLE&gt;Have fun&lt;/TITLE&gt;

&lt;/HEAD&gt;

&lt;BODY&gt;

&lt;!-- Converted from text/plain format --&gt;&lt;P&gt;&lt;FONT SIZE=2&gt;When: 
Wednesday, March 28, 2012 3:00 AM-4:00 AM. (GMT-08:00) Pacific Time (US &amp;amp; 
Canada)&lt;BR&gt;

Where: some location&lt;BR&gt;&lt;BR&gt;

*~*~*~*~*~*~*~*~*~*&lt;BR&gt;&lt;BR&gt;&amp;nbsp;some body 
here&lt;BR&gt;&lt;/FONT&gt;&lt;/P&gt;&lt;/BODY&gt;&lt;/HTML&gt;</d:htmldescription>

<d:hasattachment xmlns:d="urn:schemas:httpmail:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" 
b:dt="boolean">0</d:hasattachment>

<e:busystatus xmlns:e="urn:schemas:calendar:">TENTATIVE</e:busystatus>

<d:textdescription xmlns:d="urn:schemas:httpmail:">When: Wednesday, March 28, 2012 3:00 
AM-4:00 AM. (GMT-08:00) Pacific Time (US &amp; Canada) Where: some 
location*~*~*~*~*~*~*~*~*~* some body here

</d:textdescription>

         <e:alldayevent xmlns:e="urn:schemas:calendar:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" b:dt="boolean">0</e:alldayevent>

         <e:reminderoffset xmlns:e="urn:schemas:calendar:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" b:dt="int">900</e:reminderoffset>

         <e:dtstart xmlns:e="urn:schemas:calendar:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" 
b:dt="dateTime.tz">2012-03-28T10:00:00.000Z</e:dtstart>

         <e:dtend xmlns:e="urn:schemas:calendar:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" 
b:dt="dateTime.tz">2012-03-28T11:00:00.000Z</e:dtend>

         <e:created xmlns:e="urn:schemas:calendar:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" 
b:dt="dateTime.tz">2012-03-08T10:49:58.000Z</e:created>

         <e:recurrenceid xmlns:e="urn:schemas:calendar:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" 
b:dt="dateTime.tz">2012-03-11T10:00:00.000Z</e:recurrenceid>

         <e:lastmodified xmlns:e="urn:schemas:calendar:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" 
b:dt="dateTime.tz">2012-04-10T14:29:08.000Z</e:lastmodified>

      </a:prop>

   </a:propstat>

   <a:propstat>

      <a:status>HTTP/1.1 404 Resource Not Found</a:status>

      <a:prop>

         <f:to xmlns:f="urn:schemas:mailheader:"/>

         <f:cc xmlns:f="urn:schemas:mailheader:"/>

         <g:nonsendableto xmlns:g="http://schemas.microsoft.com/mapi/"/>

         <f:from xmlns:f="urn:schemas:mailheader:"/>

         <e:organizer xmlns:e="urn:schemas:calendar:"/>

      </a:prop>

   </a:propstat>

</a:response>

DEBUG 13:52:37,509 | AGGREGATED_CALENDAR:65 | [   ] Event with missing information, 
subject:Have fun

Step 8 Query for additional event details.

DEBUG 13:52:37,509 | AGGREGATED_CALENDAR:65 | [   ] Search Query:

<?xml version='1.0'?><d:searchrequest xmlns:d="DAV:"><d:sql>SELECT 
"urn:schemas:mailheader:to" ,"urn:schemas:mailheader:cc", "urn:schemas:mailheader:from" , 
"urn:schemas:calendar:organizer"  FROM Scope('SHALLOW TRAVERSAL OF 
"https://198.51.100.35/exchange/vm2007/calendar"')  WHERE 
"urn:schemas:calendar:instancetype" = 1 AND "urn:schemas:calendar:uid" = 
'040000008200E00074C5B7101A82E008000000006C327C3319FDCC010000000000000000100000003AD41318C
FA170488967581FBBC63202' </d:sql></d:searchrequest>

INFO  13:52:37,518 | AGGREGATED_CALENDAR:78 | [   ] Number of events we got: 1

TRACE 13:52:37,519 | AGGREGATED_CALENDAR:53 | [   ] Response Document: <?xml version="1.0" 
encoding="UTF-16"?><a:multistatus xmlns:a="DAV:" 
xmlns:b="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/" xmlns:c="xml:" 
xmlns:d="urn:schemas:mailheader:" xmlns:e="urn:schemas:calendar:">

   <a:response>

      <a:href>https://198.51.100.35/exchange/vm2007/Calendar/Have%20fun.EML</a:href>

      <a:propstat>

         <a:status>HTTP/1.1 200 OK</a:status>

         <a:prop>

            <d:to>"vm2010" &lt;vm2010@ex7aquila.com&gt;, "vm2007" 
&lt;vm2007@ex7aquila.com&gt;</d:to>

            <d:cc>&lt;vm2003@ex3aquila.com&gt;</d:cc>

            <d:from>"vm2010" &lt;vm2010@ex7aquila.com&gt;</d:from>

            <e:organizer>"vm2010" &lt;vm2010@ex7aquila.com&gt;</e:organizer>

         </a:prop>

      </a:propstat>

   </a:response>

</a:multistatus>

Step 9 Dump all returned events.

DEBUG 13:52:37,521 | AGGREGATED_CALENDAR:65 | [   ] Event Object: 
eventId:040000008200E00074C5B7101A82E008000000006C327C3319FDCC010000000000000000100000003A
D41318CFA170488967581FBBC63202@2012-03-11T10:00:00.000Z subject:Have fun

location: some location

organizer:

email : vm2010@ex7aquila.com

screenName :

fullName : vm2010

attendees: [

    email : vm2007@ex7aquila.com

    screenName :

    fullName : vm2007,

    email : vm2003@ex3aquila.com

    screenName :

    fullName : ]

nonSendableTo:

required: null

resource: null

htmlDescription: null

hasattachment: false

importance: null

allDayEvent: false

reminderOffset: 900

href: https://198.51.100.35/exchange/vm2007/Calendar/Have%20fun-5.EML

busyStatus: TENTATIVE

textDescription:When: Wednesday, March 28, 2012 3:00 AM-4:00 AM. (GMT-08:00) Pacific Time 
(US & Canada)

Where: some location *~*~*~*~*~*~*~*~*~* some body here

startDate: Wed Mar 28 10:00:00 GMT 2012

endDate: Wed Mar 28 11:00:00 GMT 2012

isRecurring: true

recurrencePattern: null

hasPartialMeetingData: false

webExDetails: {

    null

DEBUG 13:52:37,531 | AGGREGATED_CALENDAR:65 | [   ] Event Object:

  
eventId:040000008200E00074C5B7101A82E008000000006C5CD2E7F2F2CC01000000000000000010000000A6
30507C9F849A4D9D57EC07207E54ED@

subject:VM2010 is a host vm 2007 is invitee

location: Location

organizer:

email : vm2010@ex7aquila.com

screenName :

fullName : vm2010

attendees: [

    email : vm2007@ex7aquila.com

    screenName :

   fullName : vm2007]

nonSendableTo:

required: null

resource: null

htmlDescription: null

hasattachment: false

importance: null

allDayEvent: false

reminderOffset: 900

href: 
https://198.51.100.35/exchange/vm2007/Calendar/VM2010%20is%20a%20host%20vm%202007%20is%20i
nvitee-2.EML

busyStatus: TENTATIVE

textDescription:When: Wednesday, March 28, 2012 11:00 AM-12:00 PM. (GMT-08:00) Pacific 
Time (US & Canada)

Where: Location *~*~*~*~*~*~*~*~*~* Body

startDate: Wed Mar 28 18:00:00 GMT 2012

endDate: Wed Mar 28 19:00:00 GMT 2012

isRecurring: false

recurrencePattern: null

hasPartialMeetingData: false

webExDetails: {

    null

...

Step 10 Cache asynchronously the list of received WebDav events.

	DEBUG 13:52:37,567 | AGGREGATED_CALENDAR:65 | [   ] cacheListEvents:[AggCalCacheUtil]: 
[7] meetings cached for [Mail-Chain-10195-1410026_Sun Mar 25 21:00:00 GMT 2012_Sun May 06 
20:59:59 GMT 2012]

Step 11 Cache asynchronously each WebDav event.

DEBUG 13:52:37,568 | AGGREGATED_CALENDAR:65 | [   ] cacheMeeting:[AggCalCacheUtil]: 
Meeting cached for 
[040000008200E00074C5B7101A82E008000000006C327C3319FDCC010000000000000000100000003AD41318C
FA170488967581FBBC63202@2012-03-11T10:00:00.000Z-10195-1410026]

...

Selecting a Domino Event from the List of Events

The following messages are logged when a Domino event is clicked to be expanded in the list of events. The event has not been previously cached.

Step 1 Initiating call to the VDL local service.

DEBUG 14:37:44,494 | AGGREGATED_CALENDAR:65 | [   ] getMeetingDetails() method from 
AggregatedCalendarLocalServiceImpl called.

Step 2 Display the Domino settings that are used to connect to Domino.

DEBUG 14:37:44,504 | AGGREGATED_CALENDAR:65 | [   ] Using Domino Calendar settings for 
user: "r3". Username: "vmdomino domino", Password: "****", URL: "198.51.100.35", Domain: 
"dominotest"

Step 3 Try to get the events for Domino from the cache without success.

INFO  14:37:44,507 | AGGREGATED_CALENDAR:78 | [   ] getCachedEvent:[AggCalCacheUtil]: 
Cache miss for 
[C5F48FA61382B436C22579DE003AE145-1335456000000-1335459600000-10195-14610005]

Step 4 Initiate a call to the Domino server.

INFO  14:37:44,507 | AGGREGATED_CALENDAR:78 | [   ] Get events with ID 
C5F48FA61382B436C22579DE003AE145-1335456000000-1335459600000

INFO  14:37:44,512 | AGGREGATED_CALENDAR:78 | [   ] Domino session was successfully 
created for user: vmdomino domino

Step 5 Log a message just before the Domino call is initiated.

DEBUG 14:37:44,527 | AGGREGATED_CALENDAR:65 | [   ] Get meeting details for event: 
C5F48FA61382B436C22579DE003AE145-1335456000000-1335459600000

Step 6 Parse each Domino meeting attendees by common name (CN).

DEBUG 14:37:44,534 | AGGREGATED_CALENDAR:65 | [   ] Search user document for common name: 
CN=vmdomino domino

DEBUG 14:37:44,544 | AGGREGATED_CALENDAR:65 | [   ] Search user document for common name: 
CN=no mail

Step 7 Cache the event after it has been successfully retrieved.

DEBUG 14:37:44,557 | AGGREGATED_CALENDAR:65 | [   ] cacheMeeting:[AggCalCacheUtil]: 
Meeting cached for 
[C5F48FA61382B436C22579DE003AE145-1335456000000-1335459600000-10195-14610005]

Framework Logs

This section is organized as follows:

•Incorrect Theme ID

Incorrect Theme ID

ERROR [org.apache.velocity] - [TP-Processor49]: Exception in macro #content_include called 
at _SERVLET_CONTEXT_/html/themes/classic/templates/portal_normal.vm[line 559, column 33]

If you see this error, it is probably the theme ID that is misconfigured. Check if these advanced portal properties have values as follows:

default.regular.theme.id = albani

control.panel.layout.regular.theme.id = albani

Streams Logs

This section is organized as follows:

•Errors During Interpretation

•VDL Backend Debugging

Errors During Interpretation

The most common exceptions when interpreting social activities are due to permission related errors (when accessing resources like documents or images). If any other type of exception appears when interpreting a social activity, that activity is ignored when displaying the list of activities to the user in which case you would usually see a log entry similar to:

quad-web-2.example.com 2012-04-17 20:52:22,522 ERROR [socialActivities] - [TP-Processor42] 
- [alafemin] - [10B879E3B61F30994AEE245D77F8F84B.quad-web-2.example.comjvm]: 
PostActivityInterpreter.doInterpretToJSON : Cannot interpret private activity.

quad-web-2.example.com 2012-04-17 20:52:22,523 ERROR 
[social.model.BaseSocialActivityInterpreter] - [TP-Processor42] - [alafemin] - 
[10B879E3B61F30994AEE245D77F8F84B.quad-web-2.example.comjvm]: Unable to interpret activity

 com.liferay.portal.PortalException: Cannot interpret private activity.

Note that this type of error is logged even for activities that are excluded from the user Streams for normal reasons such as privacy so they do not necessarily mean exceptions.

VDL Backend Debugging

If you want to debug Streams API calls on the backend, enable Debug logging for SocialActivity Application (see Streams FAQs) then look for the following in the App Server logs:

•When you refresh the Home page or navigate to it:

Apr 25 18:08:01 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor47]: getUserActivities for 110060: Start

Apr 25 18:08:01 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor47]: getUserActivities for 110060, ResultSize:1, Time:21msecs: End

Where:

getUserActivities is the API called, 110060 is the userid, ResultSize shows how many activities have been returned, Time shows how long this call took.

•When you navigate to your profile:

Apr 25 18:32:16 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor44]: getUserPublicActivities for 110060: Start

Apr 25 18:32:16 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor44]: getUserPublicActivities for 110060, ResultSize:3, Time:2msecs: End

•When you navigate to the profile of another user:

Apr 25 18:37:06 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor47]: getUserPulbicActivities for 110112: Start

Apr 25 18:37:06 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor47]: getUserPublicActivities for 110112, ResultSize:1, Time:1msecs: End

Where:

1100112 is user ID of the user whose profile activities you are requesting.

•If a certain activity does not appear on the Home page, check if it is supposed to be there. If it is supposed to appear, then check the logs for errors.

If there is an error returning the activity to the user interface, you see a warning like this followed by an exception:

Ignoring activity due to an error while building activity entry for cnId = 
<classname_id>, cpk = <postid or documentid etc.>

If there is an error during the activity creation process, it is logged. The example that follows is for a successful post creation activity. In case of an error you see the start message but not the end message and an exception is logged.

Apr 25 18:36:42 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor44]: handleSync for POST_CREATE: classNameId =  10060, classPK= 2500002: 
Start

Apr 25 18:36:42 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor44]: PostActivityHandler:handleSynchProcess: for POST_CREATE: classNameId 
=  10060, classPK= 2500002: Start

Apr 25 18:36:42 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor44]: PostActivityHandler:handleSynchProcess: for POST_CREATE: classNameId 
=  10060, classPK= 2500002, Time:7msecs: End

Apr 25 18:36:42 ecp-10-194-189-67.example.com quad[]: DEBUG [socialActivities] - 
[TP-Processor44]: handleSync for POST_CREATE: classNameId =  10060, classPK= 2500002, 
Time:7msecs: End

•If DEBUG has been enabled for the QUAD_EVENTING log category:

Apr 25 18:36:42 ecp-10-194-189-67.example.com quad[]: DEBUG [QUAD_EVENTING] - 
[TP-Processor44]: Sending event POST_CREATE

Apr 25 18:36:42 ecp-10-194-189-67.example.com quad[]: DEBUG [QUAD_EVENTING] - 
[TP-Processor44]: Event content for event: POST_CREATE: 
{"addedRecipients":[{"class":"com.cisco.ecp.vdl.post.model.impl.PostRecipientImpl","id
":110112,"permission":{"allPermissions":null,"authorize":true,"authorized":true,"class
":"com.cisco.ecp.vdl.post.model.impl.PostPermissionImpl","comment":true,"commentable":
true,"edit":true,"editable":true,"share":true,"shared":true,"view":true,"viewable":tru
e},"recipientType":"USER"}],"attachmentInfo":{"attachments":[],"class":"com.cisco.ecp.
vdl.attachment.PostAttachmentInfoImpl","postVersion":1,"tnailURLs":[],"totalNumAttachm
ents":0},"class":"com.cisco.ecp.vdl.event.model.impl.post.PostCreateEvent","classNameI
d":10060,"classPK":2500002,"clientIp"...

Apr 25 18:36:42 ecp-10-194-189-67.example.com ...: 
0,"companyId":10193,"content":"hello 
sucharitha","eventCreatorFirstName":"shanthi","eventCreatorMedium1PortraitId":110561,"
eventCreatorMedium2PortraitId":110562,"eventCreatorMedium3PortraitId":3610011,"eventCr
eatorName":"shanthi 
n","eventCreatorScreenName":"shanthi","eventCreatorSmallPortraitId":110560,"eventCreat
orUserId":110112,"eventCreatorUtil":null,"eventTime":1335379001899,"eventType":"POST_C
REATE","excludes":["addedRecipients.recipient"],"extraAttributes":null,"includes":null
,"mentionedUsers":[],"ownerName":"shanthi 
n","ownerScreenName":"shanthi","ownerUserId":110112,"postType":"MICRO_POST","publicSco
pe":true,"quadServerIp":0,"question":false,"quickComment":"","tags":[],"title":"hello 
sucharitha","version":1}

Email Integration Logs

This section is organized as follows:

•Successfully Sent an Instant Email Notification

•Successfully Sent an Email Digest

•Problem with Connection to Postfix

•No Active SMTP Server or No SMTP Server Defined in Configuration

•VTL Syntax Error in Template File

•Expected Warning Message in Worker Log

•An Email is Sent Following a User Action

•Email Sent to a Community or a Discussion Category

Successfully Sent an Instant Email Notification

These log messages appear when an instant email notification has been sent successfully.

2012-04-27 11:07:25,660 DEBUG [InstantListener:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] An instant notification 
message received. Message: ActiveMQObjectMessage {commandId = 22, responseRequired = true, 
messageId = ID:dodo-dido.dev.example.com-40208-1335524786989-4:1:10:1:1, 
originalDestination = null, originalTransactionId = null, producerId = 
ID:dodo-dido.dev.example.com-40208-1335524786989-4:1:10:1, destination = 
queue://com.cisco.ecp.outbound.instant.notifications.queue.dido, transactionId = null, 
expiration = 0, timestamp = 1335524845647, arrival = 0, brokerInTime = 1335524834490, 
brokerOutTime = 1335524834490, correlationId = null, replyTo = null, persistent = true, 
type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, 
compressed = false, userID = null, content = 
org.apache.activemq.util.ByteSequence@74bf5c86, marshalledProperties = null, dataStructure 
= null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = true, 
readOnlyBody = true, droppable = false}

2012-04-27 11:07:25,675 DEBUG [MailTransport:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] SMTP configuration being 
used: protocol: smtp, host: 10.62.72.190, port: 25, user: null

2012-04-27 11:07:25,701 DEBUG [TemplateEngineImpl:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] Start processing the 
template for event with ID: 4ac4f98e-e9b0-481b-97e2-3112c9b8f7f0

2012-04-27 11:07:25,768 DEBUG [TemplateEngineImpl:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] Template path for event 
with ID '4ac4f98e-e9b0-481b-97e2-3112c9b8f7f0':follow_me.vm

2012-04-27 11:07:25,794 DEBUG [TemplateEngineImpl:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] Template for event with ID 
'4ac4f98e-e9b0-481b-97e2-3112c9b8f7f0' processed successfully. The generated content is: 
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" 
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">

<html xmlns="http://www.w3.org/1999/xhtml">

<head>

</head>

<body style="background-color: #e5e7e6; margin: 0px" alink="#0086C0" link="#0086C0" 
vlink="#0086C0" bgcolor="#e5e7e6">

    <table cellpadding="0" cellspacing="0" align="center" width="583" bgcolor="#ffffff" 
border="0">

        <tbody>

            <tr height="15" bgcolor="#e5e7e6">

                <td colspan="4"></td>

            </tr>

            <tr>

                <td width="37"><img src="cid:instant_images_01.gif" alt="" /></td>

                <td align="right" colspan="2" width="543"><img 
src="cid:instant_images_ltr_03.jpg" alt="Cisco Quad" /></td>

                <td width="37"><img src="cid:instant_images_02.gif" alt="" /></td>

            </tr>            <tr>

                <td width="25"></td>

                <td colspan="2" style="padding: 10px 0 13px 0;">

                    <table dir="ltr" cellpadding="0" cellspacing="0" border="0" 
width="543">

                        <tr height="10">

                            <td colspan="9"></td>

                        </tr>

                        <tr>

                            <td colspan="9"><a href="http://localhost/web/test" 
style="text-decoration: none"><font

                                    face="arial" size="2" color="#0086C0">Test 
Test</font></a> <font face="arial"

                                size="2"> is following you.</font></td>

                        </tr>

                        <tr height="10">

                            <td colspan="9"></td>

                        </tr>

                        <tr>

                            <td width="75" valign="top"><a 
href="http://localhost/web/test"><img src="cid:followerImage"

                                    alt="Test Test" width="64" height="64" border="0" 
/></a></td>

                            <td style="padding-right: 10px"><font face="arial" size="2"> 
<b>Test Test</b><br />

                                    <br />  <br />

                            </font> <a href="mailto:test@example.com" 
style="text-decoration: none"><font color="#0086C0"

                                    size="2" face="arial">test@example.com</font></a></td>

                            <td align="center" height="64" style="white-space: nowrap;">

                                <table style="border-collapse: collapse;" border="1" 
bordercolor="#AEAEAE"

                                    celpadding="0" cellspacing="0">

                                    <tr>

                                        <td bgcolor="#F8F8F8" width="200" height="30" 
align="middle"><a

                                            href="http://localhost/web/test" 
style="text-decoration: none"><font face="arial"

                                                size="2" nowrap="0" 
color="#000000"><b>View Profile</b></font></a></td>

                                    </tr>

                                </table>

                            </td>

                            <td width="10">&nbsp;</td>

                            <td align="center" height="64" style="white-space: nowrap">

                                <table style="border-collapse: collapse;" border="1" 
bordercolor="#7FC31C"

                                    celpadding="0" cellspacing="0">

                                    <tr>

                                        <td bgcolor="#2B9A00" width="100" height="30" 
align="middle"><a

                                            
href="http://localhost/c/portal/user_follow?followerId=1210101&followingId=810258" 
style="text-decoration: none"><font

                                                face="arial" size="2" nowrap="0" 
color="#ffffff"><b>Follow</b></font></a></td>

                                    </tr>

                                </table>

                            </td>

                        </tr>

                    </table>

                </td>

                <td width="25"></td>

            </tr>

            <!-- FOOTER_START_TAG -->

<!-- do not edit or remove the above tag -->

<tr>

    <td><img src="cid:instant_images_06.gif" alt="" /></td>

    <td colspan="2" width="543"></td>

    <td><img src="cid:instant_images_07.gif" alt="" /></td>

</tr>

<tr height="15" bgcolor="#e5e7e6"><td colspan="4"></td></tr>

<tr bgcolor="#e5e7e6" height="60" dir="ltr">

    <td width="37">&nbsp;</td>

    <td colspan="2" dir="ltr">

        <font color="#666666" size="1" face="arial">

            This message was send to dido@dodo.local.<br />

            If you do not wish to receive emails of this type, visit your account settings 
to manage

        </font>

        <a 
href="http://localhost/group/control_panel/manage?p_p_id=2&p_p_lifecycle=0&p_p_state=maxim
ized&p_p_mode=view&_2_struts_action=%2Fmy_account%2Fedit_user&_2_backURL=%2Fweb%2Fdido#ema
ilNotificationsQuad" style="text-decoration: none"><font color="#0086C0" size="1" 
face="arial">email notifications</font></a><font color="#666666" size="1" 
face="arial">.</font><br />

            <font color="#666666" size="1" face="arial">Please do not reply to this 
email.</font>

        </td>

    <td width="37">&nbsp;</td>

</tr>

<tr bgcolor="#e5e7e6">

    <td width="37">&nbsp;</td>

            <td width="58"><img src="cid:images_logo.gif" alt='Cisco' /></td>

        <td width="400"><font color="#666666" size="1" face="arial" align="left">&copy; 
2012 Cisco System, Inc. All rights reserved.</font></td>

    <td width="37">&nbsp;</td>

</tr>

            </tbody>

        </table>

    </body>

</html>

2012-04-27 11:07:25,810 DEBUG [SMTPHeadersInstantUtil:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] Start generating SMTP 
headers for event with ID: 4ac4f98e-e9b0-481b-97e2-3112c9b8f7f0

2012-04-27 11:07:25,811 DEBUG [SMTPHeadersInstantUtil:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] [Message-ID] Header: 
<quad-8c20c6ebd86f4f4e8cb9ceabcde2d4d5-810258-1335524845811@dodo.local>

2012-04-27 11:07:25,813 DEBUG [SMTPHeadersInstantUtil:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] [Date] Header: Apr 27, 2012

2012-04-27 11:07:25,817 DEBUG [SMTPHeadersInstantUtil:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] [Subject] Header: Test Test 
is following you

2012-04-27 11:07:25,822 DEBUG [SMTPHeadersInstantUtil:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] [To] Header: Diyan Yordanov 
<dido@dodo.local>

2012-04-27 11:07:25,826 DEBUG [SMTPHeadersInstantUtil:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] [From] Header: Cisco Quad 
<noreply@dodo.local>

2012-04-27 11:07:25,832 DEBUG [SMTPHeadersInstantUtil:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] [Sender] Header: Cisco Quad 
<noreply@dodo.local>

2012-04-27 11:07:25,898 DEBUG [MailSender:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] Thumbnail for image 
'/14/10/06/4592ba37/924d/4053/bae1/984aabe5e042.jpg' encoded in : 63 milliseconds

2012-04-27 11:07:26,380 DEBUG [MailSender:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] successfully send email for 
event 4ac4f98e-e9b0-481b-97e2-3112c9b8f7f0

2012-04-27 11:07:26,381 DEBUG [InstantListener:65] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] An instant notification 
message processed successfully. Message ID: 
ID:dodo-dido.dev.example.com-40208-1335524786989-4:1:10:1:1

Successfully Sent an Email Digest

These log messages appear when an email digest has been sent successfully.

2012-04-27 11:31:22,831 DEBUG [DigestListener:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] A digest notification 
message received. Message: ActiveMQObjectMessage {commandId = 5, responseRequired = true, 
messageId = ID:dodo-dido.dev.example.com-34675-1335526282656-2:1:1:1:1, 
originalDestination = null, originalTransactionId = null, producerId = 
ID:dodo-dido.dev.example.com-34675-1335526282656-2:1:1:1, destination = 
queue://com.cisco.ecp.outbound.digest.notifications.queue.dido, transactionId = null, 
expiration = 0, timestamp = 1335526282828, arrival = 0, brokerInTime = 1335526271961, 
brokerOutTime = 1335526271961, correlationId = null, replyTo = null, persistent = true, 
type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, 
compressed = false, userID = null, content = 
org.apache.activemq.util.ByteSequence@16d1581c, marshalledProperties = null, dataStructure 
= null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = true, 
readOnlyBody = true, droppable = false}

2012-04-27 11:31:22,841 DEBUG [MailTransport:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] SMTP configuration being 
used: protocol: smtp, host: 10.62.72.191, port: 25, user: null

2012-04-27 11:31:22,844 DEBUG [TemplateEngineImpl:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] Start processing the 
template for event with ID: testDigest

2012-04-27 11:31:22,872 DEBUG [QuadHighlightsContext:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] processed follow events 
{messageFormat=class java.text.MessageFormat, dir=ltr, locale=en_US, 
peopleContextBean=com.cisco.ecp.outbound.template.context.mail.bean.PeopleContextBean@3cbc
e6b6, 
emailSettingsURL=http://localhost/group/control_panel/manage?p_p_id=2&p_p_lifecycle=0&p_p_
state=maximized&p_p_mode=view&_2_struts_action=%2Fmy_account%2Fedit_user&_2_backURL=%2Fweb
%2Fdodo#emailNotificationsQuad, 
languageUtil=com.liferay.portal.language.LanguageImpl@2ed80128, 
subscriberEmail=dodo@dodo.local}

2012-04-27 11:31:22,892 DEBUG [QuadHighlightsContext:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] processed digest event 
{userId: 1210053, follow events: [ { {event id: 0637667d-cd83-46c6-8089-33d5e7f07034 , 
event type: FOLLOW_MUTUAL, action user: {{id: 810258, url: http://localhost/web/test}, 
display name: Test Test, image id: 1410062, email address: test@example.com, organization: 
[]} , eventTime:1335526313124, subscribedUsers=null} , followee:  {{id: 1210053, url: 
http://localhost/web/dodo}, display name: dodo dodo, image id: 1410018, email address: 
dodo@dodo.local, organization: [,]} } ,], community events: [], watch events: [], 
discussion events: []}

2012-04-27 11:31:22,893 DEBUG [TemplateEngineImpl:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] Template path for event with 
ID 'testDigest':quad_digest.vm

2012-04-27 11:31:22,923 DEBUG [TemplateEngineImpl:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] Template for event with ID 
'testDigest' processed successfully. The generated content is: <html>

<head>

<title>Template Digest</title>

</head>

<body style="background-color: #e5e7e6; margin: 0px" alink="#0086C0" link="#0086C0" 
vlink="#0086C0" bgcolor="#e5e7e6">

    <table cellpadding="0" cellspacing="0" align="center" width="570" bgcolor="#ffffff" 
border="0">

        <tbody>

            <tr>

                <td><img src="cid:digest_images_01.gif" /></td>

                <td bgcolor="#0093E1" colspan="2" align="left" width="600">

                    <div style="padding: 0 0 0 0">

                         <font color="#ffffff" size="3" face="arial">Quad Activity 
Snapshot | <font face='arial' size = '2'>Apr 20 - Apr 27</font></font>

                    </div>

                </td>

                <td><img src="cid:digest_images_02.gif" /></td>

            </tr>

            <tr>

                <td></td>

                <td colspan="2">

                    <table cellpadding="0" cellspacing="0" border="0" width="530">

                        <!-- 'People' section -->

<tr>

        <td colspan="3" height="20"></td>

</tr>

<tr height="20">

    <td align="left" colspan="2">

        <font face="arial" size="4" color="#3f3f3f">People</font>

    </td>

    <td align="right" valign="bottom">

        <a 
href="http://localhost/web/people/about-us?p_p_id=11&p_p_lifecycle=0&p_p_state=maximized&p
_p_mode=view&p_p_col_id=column-1&p_p_col_count=1&_11_struts_action=%2Fdirectory%2Fview&_11
_cmd=&_11_tabs1=users-myfollowers&_11_keywords=___" style="text-decoration: none">

            <font face="arial" size="2" color="#0086C0">View Followers</font>

        </a>

    </td>

</tr>

<tr>

    <td colspan="3" height="7"></td>

</tr>

<tr>

    <td colspan="3" height="3" bgcolor="#747474"></td>

</tr>

<tr>

    <td colspan="3" height="58">

<table cellpadding="0" cellspacing="0">

                    <tr>

                <td><a href="http://localhost/web/test" style="text-decoration: none"><img 
src="cid:1410062" alt="Test Test" width="31" height="31" border="0"/></a></td>

                <td>&nbsp;&nbsp;

                    <a href="http://localhost/web/test" style='text-decoration: 
none'><font face='arial' size='2' color='#0086C0'>Test Test</font></a><font face='arial' 
size='2'> is following you</font>.                    &nbsp;

                <a 
href="http://localhost/c/portal/user_follow?followerId=1210053&followingId=810258" 
style="text-decoration: none"><font face="arial" size="2" 
color="#0086C0">Follow</font></a>

                </td>

            </tr>

                </table>

    </td>

</tr>

                        <!-- 'Posts & Updates' section -->

<tr>

    <td colspan="3" height="22"></td>

</tr>

<tr height="20">

    <td align="left" colspan="2">

        <font face="arial" size="4" color="#3f3f3f">Posts & Updates</font>

    </td>

    <td align="right" valign="bottom">

        <a 
href="http://localhost/user/dodo?p_p_id=ACTIVITIES_WATCHLIST&_ACTIVITIES_WATCHLIST_filterT
ype=WATCHLIST_FILTER" style="text-decoration: none">

            <font face="arial" size="2" color="#0086C0">View Watch List</font>

        </a>

    </td>

</tr>

<tr>

    <td colspan="3" height="7"></td>

</tr>

<tr>

    <td colspan="3" height="3" bgcolor="#747474"></td>

</tr>

<tr>

    <td colspan="3" height="5"></td>

</tr>

        <tr>

            <td colspan="3">

                <font face='arial' size='2'>

                    No new post or update events.

                </font>

            </td>

        </tr>

                        <!-- 'Community Memberships' -->

<tr>

    <td colspan="3" height="27"></td>

</tr>

<tr height="20">

    <td align="left" colspan="3">

        <font face="arial" size="4" color="#3f3f3f">Community Memberships</font>

    </td>

    <td align="right" valign="bottom"></td>

</tr>

<tr>

    <td colspan="3" height="8"></td>

</tr>

<tr>

    <td colspan="3" height="3" bgcolor="#747474"></td>

</tr>

<tr>

    <td colspan="3" height="4"></td>

</tr>

<tr>

    <td colspan="3">

        <font face='arial' size='2'>

            No new community membership events.

        </font>

    </td>

</tr>

                        <!-- 'Community Discussions' -->

<tr>

    <td colspan="3" height="35"></td>

</tr>

<tr height="20">

    <td align="left" colspan="2"><font face="arial" size="4" color="#454545">Community 
Discussions</font>

    </td>

    <td align="right" valign="bottom">

        <a 
href="http://localhost/web/my-communities/about-us/-/communities/view/communities-joined/m
aximized" style="text-decoration: none">

            <font face="arial" size="2" color="#0086C0">View My communities</font>

        </a>

    </td>

</tr>

<tr>

    <td colspan="3" height="7"></td>

</tr>

<tr>

    <td colspan="3" height="3" bgcolor="#747474"></td>

</tr>

<tr>

    <td colspan="3" height="5"></td>

</tr>

        <tr>

            <td colspan="3">

                <font face='arial' size='2'>

                    No new community discussion events.

                </font>

            </td>

        </tr>

    <tr>

        <td colspan="3" height="25"></td>

    </tr>

                    </table>

                </td>

                <td></td>

            </tr>

            <!-- FOOTER_START_TAG -->

<!-- do not edit or remove the above tag -->

<tr>

    <td><img src="cid:digest_images_06.gif" alt="" /></td>

    <td colspan="2" width="543"></td>

    <td><img src="cid:digest_images_07.gif" alt="" /></td>

</tr>

<tr height="15" bgcolor="#e5e7e6"><td colspan="4"></td></tr>

<tr bgcolor="#e5e7e6" height="60">

    <td width="37">&nbsp;</td>

    <td colspan="2">

        <font color="#666666" size="1" face="arial">

            This message was send to dodo@dodo.local.<br />

            If you do not wish to receive emails of this type, visit your account settings 
to manage

        </font>

        <a 
href="http://localhost/group/control_panel/manage?p_p_id=2&p_p_lifecycle=0&p_p_state=maxim
ized&p_p_mode=view&_2_struts_action=%2Fmy_account%2Fedit_user&_2_backURL=%2Fweb%2Fdodo#ema
ilNotificationsQuad" style="text-decoration: none"><font color="#0086C0" size="1" 
face="arial">email notifications</font></a><font color="#666666" size="1" 
face="arial">.</font><br />

        </td>

    <td width="37">&nbsp;</td>

</tr>

<tr bgcolor="#e5e7e6">

    <td width="37">&nbsp;</td>

    <td width="58"><img src="cid:images_logo.gif" alt='Cisco' /></td>

    <td width="400"><font color="#666666" size="1" face="arial" align="left">&copy; 2012 
Cisco System, Inc. All rights reserved.</font></td>

    <td width="37">&nbsp;</td>

</tr>

            </tbody>

        </table>

    </body>

</html>

2012-04-27 11:31:22,928 DEBUG [SMTPHeadersDigestUtil:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] Start generating SMTP 
headers for digest notification: [UserID: 1210053, NotificationDate: Apr 27, 2012]

2012-04-27 11:31:22,928 DEBUG [SMTPHeadersDigestUtil:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] [Message-ID] Header: 
<quad-b95b9561c0b5465199fe10bd9906e1c7-1210053-1335526282928@dodo.local>

2012-04-27 11:31:22,929 DEBUG [SMTPHeadersDigestUtil:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] [Date] Header: Apr 27, 2012

2012-04-27 11:31:22,931 DEBUG [SMTPHeadersDigestUtil:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] [Subject] Header: Quad 
Activity Snapshot: Apr 20, 2012 - Apr 27, 2012

2012-04-27 11:31:22,934 DEBUG [SMTPHeadersDigestUtil:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] [To] Header: dodo dodo 
<dodo@dodo.local>

2012-04-27 11:31:22,937 DEBUG [SMTPHeadersDigestUtil:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] [From] Header: Cisco Quad 
<noreply@dodo.local>

2012-04-27 11:31:22,939 DEBUG [SMTPHeadersDigestUtil:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] [Sender] Header: Cisco Quad 
<noreply@dodo.local>

2012-04-27 11:31:22,943 DEBUG [MailSender:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] Thumbnail for image 
'/14/10/05/fc934473/f86a/4c2d/8469/d52bd6695d86.jpg' encoded in : 3 milliseconds

2012-04-27 11:31:22,959 DEBUG [MailSender:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] successfully send email for 
event testDigest

2012-04-27 11:31:22,961 DEBUG [DigestListener:65] 
[com.cisco.ecp.outbound.jms.digest.notifications.Container-1] An digest notification 
message processed successfully. Message ID: 
ID:dodo-dido.dev.example.com-34675-1335526282656-2:1:1:1:1

Problem with Connection to Postfix

These log messages appear when a problem has appeared when trying to connect to Postfix (postfix2.example.com in this example).

2012-04-27 11:14:46,998 WARN  [MailSender:98] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] Cannot send email for event 
8b3912d6-9bfb-4905-8dab-73d8af962110 using SMTP server postfix2.example.com and will retry 
with another one

org.springframework.mail.MailSendException: Mail server connection failed; nested 
exception is javax.mail.MessagingException: Unknown SMTP host: postfix2.example.com;

  nested exception is:

        java.net.UnknownHostException: postfix2.example.com. Failed messages: 
javax.mail.MessagingException: Unknown SMTP host: postfix2.example.com;

  nested exception is:

        java.net.UnknownHostException: postfix2.example.com; message exception details (1) 
are:

Failed message 1:

javax.mail.MessagingException: Unknown SMTP host: postfix2.example.com;

  nested exception is:

        java.net.UnknownHostException: postfix2.example.com

        at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1280)

        at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:370)

        at javax.mail.Service.connect(Service.java:275)

        at 
org.springframework.mail.javamail.JavaMailSenderImpl.doSend(JavaMailSenderImpl.java:389)

        at 
org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:340)

        at 
org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:355)

        at 
org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:344)

        at com.cisco.ecp.outbound.sender.mail.MailSender.sendImpl(MailSender.java:156)

        at com.cisco.ecp.outbound.sender.mail.MailSender.sendImpl(MailSender.java:175)

        at com.cisco.ecp.outbound.sender.mail.MailSender.send(MailSender.java:70)

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

        at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

        at java.lang.reflect.Method.invoke(Method.java:597)

        at 
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMet
hodInvocation.java:183)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:150)

        at 
com.liferay.portal.monitoring.ServiceMonitoringAdvice.invoke(ServiceMonitoringAdvice.java:
214)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:172)

        at 
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInt
erceptor.java:90)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:172)

        at 
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

        at $Proxy426.send(Unknown Source)

        at com.cisco.ecp.outbound.jms.InstantListener.process(InstantListener.java:178)

        at com.cisco.ecp.outbound.jms.InstantListener.onMessage(InstantListener.java:86)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(Abstrac
tMessageListenerContainer.java:561)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractM
essageListenerContainer.java:499)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(Abstra
ctMessageListenerContainer.java:467)

        at 
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecu
te(AbstractPollingMessageListenerContainer.java:325)

        at 
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute
(AbstractPollingMessageListenerContainer.java:263)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.invokeListener(DefaultMessageListenerContainer.java:1059)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.executeOngoingLoop(DefaultMessageListenerContainer.java:1051)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.run(DefaultMessageListenerContainer.java:948)

        at java.lang.Thread.run(Thread.java:662)

Caused by: java.net.UnknownHostException: postfix2.example.com

        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:195)

        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)

        at java.net.Socket.connect(Socket.java:529)

        at java.net.Socket.connect(Socket.java:478)

        at com.sun.mail.util.SocketFetcher.createSocket(SocketFetcher.java:232)

        at com.sun.mail.util.SocketFetcher.getSocket(SocketFetcher.java:189)

        at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1250)

        ... 33 more

No Active SMTP Server or No SMTP Server Defined in Configuration

These log messages appear when there are no active SMTP servers or there are not any SMTP servers defined in the configuration.

2012-04-27 11:14:46,999 ERROR [InstantListener:116] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] could not process event  { 
{event id: 8b3912d6-9bfb-4905-8dab-73d8af962110 , event type: FOLLOW, action user: {{id: 
810258, url: http://localhost/web/test}, display name: Test Test, image id: 1410062, email 
address: test@example.com, organization: []} , eventTime:1335525321868, 
subscribedUsers=[1210101]} , followee:  {{id: 1210101, url: http://localhost/web/dido}, 
display name: Diyan Yordanov, image id: 6410023, email address: dido@dodo.local, 
organization: [,]} }

com.cisco.ecp.outbound.NonRetryableSendException: bad configuration - there are no SMTP 
servers

        at 
com.cisco.ecp.outbound.sender.mail.MailTransport.reconfigure(MailTransport.java:61)

        at com.cisco.ecp.outbound.sender.mail.MailSender.sendImpl(MailSender.java:174)

        at com.cisco.ecp.outbound.sender.mail.MailSender.sendImpl(MailSender.java:175)

        at com.cisco.ecp.outbound.sender.mail.MailSender.send(MailSender.java:70)

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

        at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

        at java.lang.reflect.Method.invoke(Method.java:597)

        at 
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMet
hodInvocation.java:183)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:150)

        at 
com.liferay.portal.monitoring.ServiceMonitoringAdvice.invoke(ServiceMonitoringAdvice.java:
214)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:172)

        at 
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInt
erceptor.java:90)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:172)

        at 
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

        at $Proxy426.send(Unknown Source)

        at com.cisco.ecp.outbound.jms.InstantListener.process(InstantListener.java:178)

        at com.cisco.ecp.outbound.jms.InstantListener.onMessage(InstantListener.java:86)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(Abstrac
tMessageListenerContainer.java:561)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractM
essageListenerContainer.java:499)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(Abstra
ctMessageListenerContainer.java:467)

        at 
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecu
te(AbstractPollingMessageListenerContainer.java:325)

        at 
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute
(AbstractPollingMessageListenerContainer.java:263)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.invokeListener(DefaultMessageListenerContainer.java:1059)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.executeOngoingLoop(DefaultMessageListenerContainer.java:1051)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.run(DefaultMessageListenerContainer.java:948)

        at java.lang.Thread.run(Thread.java:662)

VTL Syntax Error in Template File

These log messages appear when a VTL syntax error has been encountered in a template file.

2012-04-29 09:36:40,254 ERROR [VelocityEngine:43] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] Parser Exception: 
reminder.vm

2012-04-29 09:36:40,256 ERROR [VelocityEngine:43] 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] 
org.apache.velocity.runtime.parser.ParseException: Encountered

"<EOF>" at line 48, column 44.

Was expecting one of:

    "(" ...

    <RPAREN> ...

    <ESCAPE_DIRECTIVE> ...

    <SET_DIRECTIVE> ...

    "##" ...

    "\\\\" ...

    "\\" ...

    <TEXT> ...

    "*#" ...

    "*#" ...

    "]]#" ...

    <STRING_LITERAL> ...

    <END> ...

    <IF_DIRECTIVE> ...

    <ELSEIF_DIRECTIVE> ...

    <ELSE_DIRECTIVE> ...

    <INTEGER_LITERAL> ...

    <FLOATING_POINT_LITERAL> ...

    <WORD> ...

    <BRACKETED_WORD> ...

    <IDENTIFIER> ...

    <DOT> ...

    "{" ...

    "}" ...

    <EMPTY_INDEX> ...

        at 
org.apache.velocity.runtime.parser.Parser.generateParseException(Parser.java:3679)

        at org.apache.velocity.runtime.parser.Parser.jj_consume_token(Parser.java:3558)

        at org.apache.velocity.runtime.parser.Parser.IfStatement(Parser.java:1740)

        at org.apache.velocity.runtime.parser.Parser.Statement(Parser.java:352)

        at org.apache.velocity.runtime.parser.Parser.process(Parser.java:317)

        at org.apache.velocity.runtime.parser.Parser.parse(Parser.java:117)

        at org.apache.velocity.runtime.RuntimeInstance.parse(RuntimeInstance.java:1226)

        at org.apache.velocity.runtime.RuntimeInstance.parse(RuntimeInstance.java:1181)

        at org.apache.velocity.Template.process(Template.java:134)

        at 
org.apache.velocity.runtime.resource.ResourceManagerImpl.refreshResource(ResourceManagerIm
pl.java:569)

        at 
org.apache.velocity.runtime.resource.ResourceManagerImpl.getResource(ResourceManagerImpl.j
ava:319)

        at 
org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:1533)

        at org.apache.velocity.app.VelocityEngine.mergeTemplate(VelocityEngine.java:343)

        at 
com.cisco.ecp.outbound.template.TemplateEngineImpl.processTemplate(TemplateEngineImpl.java
:99)

        at 
com.cisco.ecp.outbound.template.TemplateEngineImpl.getNotificationMailBean(TemplateEngineI
mpl.java:66)

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

        at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

        at java.lang.reflect.Method.invoke(Method.java:597)

        at 
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMet
hodInvocation.java:183)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:150)

        at 
com.liferay.portal.monitoring.ServiceMonitoringAdvice.invoke(ServiceMonitoringAdvice.java:
214)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:172)

        at 
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInt
erceptor.java:90)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:172)

        at 
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

        at $Proxy424.getNotificationMailBean(Unknown Source)

        at 
com.cisco.ecp.outbound.sender.mail.mime.MimeGeneratorImpl$1.prepare(MimeGeneratorImpl.java
:79)

        at 
org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:352)

        at 
org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:344)

        at com.cisco.ecp.outbound.sender.mail.MailSender.sendImpl(MailSender.java:156)

        at com.cisco.ecp.outbound.sender.mail.MailSender.send(MailSender.java:70)

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

        at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

        at java.lang.reflect.Method.invoke(Method.java:597)

        at 
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMet
hodInvocation.java:183)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:150)

        at 
com.liferay.portal.monitoring.ServiceMonitoringAdvice.invoke(ServiceMonitoringAdvice.java:
214)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:172)

        at 
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInt
erceptor.java:90)

        at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvoc
ation.java:172)

        at 
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

        at $Proxy426.send(Unknown Source)

        at com.cisco.ecp.outbound.jms.InstantListener.process(InstantListener.java:178)

        at com.cisco.ecp.outbound.jms.InstantListener.onMessage(InstantListener.java:86)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(Abstrac
tMessageListenerContainer.java:561)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractM
essageListenerContainer.java:499)

        at 
org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(Abstra
ctMessageListenerContainer.java:467)

        at 
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecu
te(AbstractPollingMessageListenerContainer.java:325)

        at 
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute
(AbstractPollingMessageListenerContainer.java:263)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.invokeListener(DefaultMessageListenerContainer.java:1059)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.executeOngoingLoop(DefaultMessageListenerContainer.java:1051)

        at 
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvok
er.run(DefaultMessageListenerContainer.java:948)

        at java.lang.Thread.run(Thread.java:662)

Expected Warning Message in Worker Log

The warning message below is logged when the user comments on a post or update and the log level for Outbound Email is INFO, DEBUG, or TRACE.

The reason this warning is logged is because the system checks if there is a parent comment to determine wether the event is a top-level comment or a reply to a comment.

In most cases these warning can be ignored, but if there is an actual problem, the provided information can be used to determine the cause.

Jun 25 18:57:45 worker.dodo.local quadworker[]: WARN  [context.mail.PostCommentContext] - 
[com.cisco.ecp.outbound.jms.instant.notifications.Container-2] - [] - []: parentcomment is 
null for event { {event id: 48e29b78-8968-4845-b1dc-ef13366c634c , event type: 
POST_COMMENT, action user: {{id: 210600, url: https://quad.dodo.local/web/tm}, display 
name: Todor Minakov, image id: 0, email address: tm@dodo.local, organization: [,]} , 
eventTime:1340650665448, subscribedUsers=[210280]} , post: {{id: 1700026, url: 
https://quad.dodo.local/web/view-post/post/-/posts?postId=1700026}, author: 210280, type: 
POST, title: My post with a lot stuff in it, summary: null}, comment: {{id: 2610480, url: 
https://quad.dodo.local/web/view-post/post/-/posts?postId=1700026&messageScrollId=2610480}
, title: null, summary: a, user:  {{id: 210600, url: https://quad.dodo.local/web/tm}, 
display name: Todor Minakov, image id: 0, email address: tm@dodo.local, organization: [,]} 
, parent comment: null}}

An Email is Sent Following a User Action

When an email event is sent based on a user action, you see a log message on the App Server node that looks similarly to the following:

Apr 25 22:35:09 test-int.example.com quad[]: DEBUG [QUAD_EVENTING] - [TP-Processor40]: 
Sending event POST_CREATE

Apr 25 22:35:09 test-int.example.com quad[]: DEBUG [QUAD_EVENTING] - [TP-Processor40]: 
Event content for event: POST_CREATE: 
{"addedRecipients":[{"class":"com.cisco.ecp.vdl.post.model.impl.PostRecipientImpl","id":11
0005,"permission":{"allPermissions":null,"authorize":false,"authorized":false,"class":"com
.cisco.ecp.vdl.post.model.impl.PostPermissionImpl","comment":false,"commentable":false,"ed
it":false,"editable":false,"share":false,"shared":false,"view":true,"viewable":true},"reci
pientType":"USER"},{"class":"com.cisco.ecp.vdl.post.model.impl.PostRecipientImpl","id":110
057,"permission":{"allPermissions":null,"authorize":false,"authorized":false,"class":"com.
c...

The above message shows a POST_CREATE event being sent to RabbitMQ when a user creates a post.

On the Worker node, a corresponding log message appears when the event is being processed by the email service:

Apr 25 22:35:09 test-int.example.com quad[]: DEBUG [digest] - [pool-3-thread-2]: 
DigestEventReceiver.processEvent(): delivery tag = 27, event = {{ eventType: POST_CREATE, 
eventTime: 1335393308458, client ip: 0, Quad Ip: 0, classPK: 4700001, classNameId: 10060, 
creator id: 10399, creator name: Compliance Officer, screen name: 
ciscosyscomplianceofficer, small portrait: 0, medium portrait 1: 0, medium portrait 2: 0, 
company id: 10193}, post version: 1, public scope: false, owner id: 10399, owner name: 
Compliance Officer, owner screen name: ciscosyscomplianceofficer, title: Solomon Wu's 
content has been hidden (Case 9010211), post type: TEXT_POST, mentioned users: []}

Email Sent to a Community or a Discussion Category

When an email has been sent to a community for processing, messages similar to the following appear in the Worker log:

2012-04-27 13:53:16,295 DEBUG [MailHandler:97] 
[org.subethamail.smtp.server.Session-/10.62.73.210:46524] Received mail for processing. 
FROM: user@example.com

2012-04-27 13:53:16,303 DEBUG [MailHandler:172] 
[org.subethamail.smtp.server.Session-/10.62.73.210:46524] Received mail for processing. 
RCPTO: 257bdfdf4f@example.com

2012-04-27 13:53:16,320 DEBUG [HookFactory:13] 
[org.subethamail.smtp.server.Session-/10.62.73.210:46524] Instantiate 
com.cisco.ecp.inbound.FileSystemHook

2012-04-27 13:53:16,325 DEBUG [HookFactory:20] 
[org.subethamail.smtp.server.Session-/10.62.73.210:46524] Return 
com.cisco.ecp.inbound.FileSystemHook

2012-04-27 13:53:16,363 DEBUG [MailHandler:68] 
[org.subethamail.smtp.server.Session-/10.62.73.210:46524] Received mail for processing. 
Sent for processing.

2012-04-27 13:53:16,364 DEBUG [MailHandler:83] 
[org.subethamail.smtp.server.Session-/10.62.73.210:46524] Received mail for processing. 
DONE.

2012-04-27 13:53:16,365 DEBUG [MailHandler:83] 
[org.subethamail.smtp.server.Session-/10.62.73.210:46524] Received mail for processing. 
DONE.

The App Server log contains the following additional messages:

Apr 27 13:29:48 appserv.example.com quad[]: DEBUG [mail.jms.InboundJmsListenerContainer] - 
[com.cisco.ecp.inbound.Container-1]: Received message of type [class 
org.apache.activemq.command.ActiveMQObjectMessage] from consumer [Cached JMS 
MessageConsumer: ActiveMQMessageConsumer { 
value=ID:appserv.example.com-39732-1335513294312-4:1:7:1, started=true }] of session 
[Cached JMS Session: ActiveMQSession 
{id=ID:appserv.example.com-39732-1335513294312-4:1:7,started=true}]

Apr 27 13:29:48 appserv.example.com quad[]: DEBUG [ecp.inbound.HookFactory] - 
[com.cisco.ecp.inbound.Container-1]: Return com.cisco.ecp.inbound.FileSystemHook

2012-06-22 09:00:36,114 DEBUG [MimeMessageCollectorImpl:158] 
[com.cisco.ecp.inbound.Container-3] Processing MIME part [headers={Content-Type: 
text/plain; charset=UTF-8; format=flowed; Content-Transfer-Encoding: 8bit; }]

2012-06-22 09:00:36,132 DEBUG [MimeMessageCollectorImpl:158] 
[com.cisco.ecp.inbound.Container-3] Processing MIME part [headers={Content-Type: 
text/html; charset=UTF-8; Content-Transfer-Encoding: 8bit; }]

2012-06-22 09:00:36,135 DEBUG [MimeMessageCollectorImpl:158] 
[com.cisco.ecp.inbound.Container-3] Processing MIME part [headers={Content-Type: 
image/jpeg;

 name="Tulips.jpg"; Content-Transfer-Encoding: base64; Content-ID: 
<part1.07080504.09090309@dev.example.com>; Content-Disposition: inline;

 filename="Tulips.jpg"; }]

Apr 27 13:29:48 appserv.example.com quad[]: DEBUG [mail.processor.MailProcessorImpl] - 
[com.cisco.ecp.inbound.Container-1]: Recipients that will process the action 
[{emailaddress=257bdfdf4f, classNameId=10087, classPK=710083, companyId=10195, 
displayName=Ope1, outgoingEmailAddress=, outgoingDisplayName=, errorReporting=3}]. Content 
should be shared with [257bdfdf4f@example.com].

 Apr 27 13:29:48 appserv.example.com quad[]: DEBUG [mail.processor.MailProcessorImpl] - 
[com.cisco.ecp.inbound.Container-1]: Parent message id [0]

Apr 27 13:29:48 appserv.example.com quad[]: DEBUG [mail.processor.MailProcessorImpl] - 
[com.cisco.ecp.inbound.Container-1]: Inline image addition for [tulips.jpg]

Apr 27 13:29:48 appserv.example.com quad[]: DEBUG [processor.action.PostMailAction] - 
[com.cisco.ecp.inbound.Container-1]: Adding a new post.

Apr 27 13:29:48 appserv.example.com quad[]: DEBUG [processor.action.PostMailAction] - 
[com.cisco.ecp.inbound.Container-1]: Creating a post [[PostImpl =>, body=<font size=2 
face="sans-serif">GIF below:</font>#015#012<br>#015#012<br><img 
src=/image/image_gallery?img_id=6810626 style=";max-width:100.0%;padding:5.0px;">, 
categoryId=1, companyId=10195, createdUserName=Ordinary Joe, creatorUserId=5910003, 
editCount=0, lastModifiedUserId=5910003, lastModifiedUserName=Ordinary Joe, 
originalPostId=-1, parentPostId=-1, postId=-1, title=LN-Embedded GIF, version=1, tags=, 
comments count=0, edit counts=0, transaction type=null, transaction user id=-1, 
transaction time=null, hasAttachments =false, uri=null, isRead=false, favorite=false, 
showOnProfile=false, publicPost=true, state=0]].

Apr 27 13:29:49 appserv.example.com quad[]: DEBUG [mail.processor.MailProcessorImpl] - 
[com.cisco.ecp.inbound.Container-1]: Recipient {emailaddress=257bdfdf4f, 
classNameId=10087, classPK=710083, companyId=10195, displayName=Ope1, 
outgoingEmailAddress=, outgoingDisplayName=, errorReporting=3} processed the mail and 
created content with id [2,600,012]

Apr 27 13:29:49 appserv.example.com quad[]: DEBUG [ecp.inbound.HookFactory] - 
[com.cisco.ecp.inbound.Container-1]: Return com.cisco.ecp.inbound.FileSystemHook

The messages that appear when the email has been sent to a discussion category are similar.

If the email is a reply and the parent email is present in WebEx Social, then the Parent message id [0] will have a value different than 0, as shown in the next example:

2012-06-22 09:00:36,347 DEBUG [ParentMessageIdentifierImpl:48] 
[com.cisco.ecp.inbound.Container-3] Parent message found by in-reply-to header 
[quad-ed0af916facd454ab18f4edabc5dcafa-34110004-1340352778537@example.com] and resource id 
28,710,004

2012-06-22 09:00:36,348 DEBUG [MailProcessorImpl:249] [com.cisco.ecp.inbound.Container-3] 
Parent message id [34,110,004]

Office Plug-in Logs

This section is organized as follows:

•User Enters Wrong Server URL in Settings

•Office Plug-in Has Loaded Successfully

•Failed Theme Update Due to Server Error

•Failed Theme Update Due to Missing Image

User Enters Wrong Server URL in Settings

These log messages appear in the office plug-in log file on the user computer when a wrong or inexistent server URL has been entered in the settings dialog box.

ERROR 2012-06-27 10:06:40 Unable to connect to the remote server    at 
System.Net.HttpWebRequest.GetRequestStream(TransportContext& context)

   at System.Net.HttpWebRequest.GetRequestStream()

   at QuadConnector.OAuth.OAuthManager.RequestPOST(String aUrl, NameValueCollection 
aHeaders, Dictionary`2 aPostDataList) in C:\work\Quad\email 
plugin\email-plugin\Source\Outlook\CommonLibs\QuadConnector\OAuth\OAuthManager.cs:line 177

In addition, this GUI error is displayed:

Office Plug-in Has Loaded Successfully

These log messages appear in the office plug-in log file on the user computer when the office plug-in has loaded successfully.

INFO 2012-06-27 11:49:15 Plugin loading. The current user is: Anatoliy Atanasov (aatanaso)

INFO 2012-06-27 11:49:16 Plugin loaded.

Failed Theme Update Due to Server Error

These log messages appear in the office plug-in log file on the user computer when a theme update has failed due to a server error:

HTTP GET request failed!

URL: https://appserver.example.com/quadopen/api/rest/config/themes?startIndex=0&count=1

... 39 more

[WARN] 07 Jun 02:01:57.412 PM main [com.cisco.ecp.email.plugin.ui.utils.UIUtils] Theme 
update failed.

com.cisco.ecp.email.plugin.exception.http.ServiceUnavailableException: 
com.cisco.ecp.email.plugin.exception.http.BaseHttpException:

Failed Theme Update Due to Missing Image

These log messages appear in the office plug-in log file on the user computer when a theme update has failed due to a image, as specified in settings.properties, missing from the theme archive.

[ERROR] 07 Jun 02:02:20.535 PM main [com.cisco.ecp.email.plugin.quad.QuadOperations] Error 
applying new branding theme: 
http://appserver.example.com/c/portal_branding?assetType=portalTheme&assetId=20410016

java.io.FileNotFoundException: 
C:\Users\abrisson\AppData\Local\Temp\ProductivityPluginTheme6753766605358143608\custom\ima
ges32_logo.png (The system cannot find the file specified.)

Cisco WebEx Social Call Plug-in Logs

This section is organized as follows:

•Error in User Configuration

Error in User Configuration

The following softphone.log log messages are an example of an error that occurrs as a result of an incorrect user configuration where the device and operation mode are incompatible.

04-May-2012 17:01:46,626 -0700 DEBUG [0x00002110] csf.ecc.api: isDeskPhone()

04-May-2012 17:01:46,626 -0700 DEBUG [0x00002110] csf.ecc.api: isSoftPhone()

04-May-2012 17:01:46,626 -0700 DEBUG [0x00002110] csf.ecc.api: getConfigStatus()

04-May-2012 17:01:46,626 -0700 DEBUG [0x00002110] csf.ecc.api: getServiceState()

04-May-2012 17:01:46,626 -0700 DEBUG [0x00002110] csf.ecc.api: getName()

04-May-2012 17:01:46,626 -0700 INFO  [0x00002110] csf.ecc.evt: PHONE_EVENT: eFound, Name: 
ecprarasike, IsDeskPhone, ServiceState: eUnknown, ConfigStatus: eFetchedConfig

04-May-2012 17:01:46,626 -0700 DEBUG [0x00002110] csf.ecc.api: getName()

04-May-2012 17:01:46,626 -0700 INFO  [0x00002110] webuc: Received Phone Event. Event: 
eFound Name: ecprarasike

04-May-2012 17:01:46,626 -0700 INFO  [0x00002110] csf.ecc.api: getLastTFTPServerUsed() = 
gigantic-6

04-May-2012 17:01:46,627 -0700 INFO  [0x00002110] webuc: Received Network Event: 2

04-May-2012 17:01:46,627 -0700 INFO  [0x00002110] webuc: Received Network Event: 0

04-May-2012 17:01:46,627 -0700 INFO  [0x00002110] csf.ecc.api: getPreferredDeviceName() =

04-May-2012 17:01:46,627 -0700 INFO  [0x00002110] csf.ecc.api: 
setLocalIpAddressAndGateway("198.51.100.35", "198.51.100.133")

04-May-2012 17:01:46,627 -0700 INFO  [0x00002110] webuc: Based on remote address: 
gigantic-6, local IP address is: 198.51.100.35 and gateway is: 198.51.100.133

04-May-2012 17:01:46,627 -0700 INFO  [0x00002110] csf.ecc.api: connect(eDeskPhone, 
ecprarasike, )

04-May-2012 17:01:46,627 -0700 ERROR [0x00002110] csf.ecc: doConnect() failed - 
credentials not specified! : eNoCredentialsConfigured

04-May-2012 17:01:46,628 -0700 INFO  [0x00002110] csf.ecc: --->

04-May-2012 17:01:46,628 -0700 INFO  [0x00002110] csf.ecc: <---

04-May-2012 17:01:46,628 -0700 ERROR [0x00002110] csf.ecc.api: connect() failed - 
doConnect() returned error : eNoCredentialsConfigured

04-May-2012 17:01:46,628 -0700 INFO  [0x00002110] webuc: Connect returned. Code: 
eNoCredentialsConfigured

04-May-2012 17:01:46,629 -0700 INFO  [0x00001f18] webuc: 
NamedMutexHelper::ReleaseWorkItem::run()

04-May-2012 17:01:46,629 -0700 INFO  [0x00001f18] webuc: about to notify

04-May-2012 17:01:46,629 -0700 INFO  [0x00002110] webuc: NamedMutexHelper::release:wait 
complete

04-May-2012 17:01:46,633 -0700 INFO  [0x000022e4] webuc: logout called

04-May-2012 17:01:46,633 -0700 INFO  [0x00002110] webuc: releaseInternal - cleaning up 
calls in preparation for disconnect

04-May-2012 17:01:46,633 -0700 INFO  [0x00002110] webuc: releasing logging

04-May-2012 17:01:46,633 -0700 INFO  [0x00002110] webuc: destroying logging file appender

In this line taken from the example above, you can see that the user is trying to use the Call Plug-in (named: ecprarasike) in deskphone mode (eDeskPhone) instead of in the correct softphone mode.

04-May-2012 17:01:46,627 -0700 INFO  [0x00002110] csf.ecc.api: connect(eDeskPhone, 
ecprarasike, )

WebEx Social for Office Logs

This section is organized as follows:

•Client Lists Attachments to a Post

•Client Lists Comments to a Post and Adds New Comment

•Client Downloads File Successfully

•Client Adds New Version of an Attachment

•Server Side Logs of the Shared Changes Feature

•Client Side Logs of the Shared Changes Feature

•User Provided Invalid Token or Invalid Credentials

Client Lists Attachments to a Post

These log messages appear on the server when the client requests the list of attachments to a post.

Apr 27 20:49:47 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor40]: updated post id=34227003

Apr 27 20:49:47 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor40]: looking up attachments for post id=34227003

Apr 27 20:49:47 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor40]: found 1 attachments for post=34227003

Apr 27 20:49:47 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor40]: after pruning dups, 1 attachments for post=34227003

Client Lists Comments to a Post and Adds New Comment

These log messages appear on the server when the client requests the list of comments to a post and then comments on the post.

Apr 27 20:49:47 quad.example.com quad[]: DEBUG [office.server.CommentController] - 
[TP-Processor39]: getComments with query 
params=discussionId=00000000-0000-0000-0000-0000020a433b

Apr 27 20:49:47 quad.example.com quad[]: DEBUG [office.server.CommentController] - 
[TP-Processor39]: get comments returning 2 comment(s)

Apr 27 20:49:47 quad.example.com quad[]: DEBUG [office.server.CommentController] - 
[TP-Processor39]: creating message on postId=34227003 parentMsgId=48463826 
threadId=48463827 as Dave Brown

Apr 27 20:49:47 quad.example.com quad[]: DEBUG [office.server.CommentController] - 
[TP-Processor39]: created msg with id=48463835 guid=00000000-0000-0000-0000-000002e37fdb

Client Downloads File Successfully

These log messages appear on the server when the client downloads a file successfully.

Apr 27 20:49:48 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor37]: done writing stream for contentId=319ae504-7d74-47d2-8234-77a2a725bf03 
version=1, 10449 bytes.

Client Adds New Version of an Attachment

These log messages appear on the server when the client uploads a new version downloads (v.2 in this case) of a file attachment.

Apr 27 20:49:53 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor47]: Update content '319ae504-7d74-47d2-8234-77a2a725bf03 (nextVersion is 
'null')

Apr 27 20:49:53 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor47]: Version is: Version{date=2012-04-27T20:49:46.920Z, 
contentId=319ae504-7d74-47d2-8234-77a2a725bf0\

3, spaceId=319ae504-7d74-47d2-8234-77a2a725bf03, member=Member, shortName='Dave Brown', 
fullName='Dave Brown', emailAddress='davebro@example.com', active=true, role=Admin}, 
comment='null', diff='null', numericV\

ersion=2, via=Unknown, 
url=/c/post_action/get_attachment?postId=34227003&postVersionId=2&attachmentId=48463833, 
md5=null, size=13467}

Apr 27 20:49:53 quad.example.com quad[]: DEBUG [office.server.PrincipalUtil] - 
[TP-Processor47]: in getId(), permission checker is 
com.liferay.portal.security.permission.CMRPermissionChecker@54b97122 o\

n thread TP-Processor47

Apr 27 20:49:53 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor47]: Data is: Version{date=2012-04-27T20:49:46.920Z, 
contentId=319ae504-7d74-47d2-8234-77a2a725bf03, \

spaceId=319ae504-7d74-47d2-8234-77a2a725bf03, member=Member, shortName='Dave Brown', 
fullName='Dave Brown', emailAddress='davebro@example.com', active=true, role=Admin}, 
comment='null', diff='null', numericVers\

ion=2, via=Unknown, 
url=/c/post_action/get_attachment?postId=34227003&postVersionId=2&attachmentId=48463833, 
md5=null, size=13467}

Apr 27 20:49:53 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor47]: creating new attachment version for 
id=319ae504-7d74-47d2-8234-77a2a725bf03, name=New_Doc.docx, \

client passed in version 2

Apr 27 20:49:53 quad.example.com quad[]: DEBUG [office.server.QuadContentController] - 
[TP-Processor47]: created content id=319ae504-7d74-47d2-8234-77a2a725bf03

Server Side Logs of the Shared Changes Feature

When users are uploading an attachment while creating or editting a post, you should see the debug messages shown below. The document is not associated with an asset (such as post) at this point as the asset has not been saved, but tagging of the document with certain information (such as version info and a UUID split into two 64-bit integers (VerslyUUID_MSB, VerslyUUID_LSB) has already been done completed.

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImpl:addAttachment:{attachmentId=49800012, companyId=100193, 
versionUserId=100256, groupId=100264, createDate=Fri Apr 27 17:57:17 GMT 2012, 
modifiedDate=Fri Apr 27 17:57:17 GMT 2012, type_=0, legacy=false, contentState=0, 
embedded=false, fileName=upgrading_ecp_test.docx, dirPath=, summary=0, 
parentClassNameId=0, parentClassPK=0, repositoryId=49800012, version=0.0, size=387476, 
extraData=, locale=, verslyUUID_MSB=0, verslyUUID_LSB=0}

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImpl:addAttachment:not yet associated with asset

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: The 
type assigned for temporary attachment is:DOCUMENT

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: Enter 
AttachmentLocalServiceImmpl::addDocumentAttachment(attachment,userId)

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]:  
AttachmentLocalServiceImmpl::addDocumentAttachment(attachment,userId): Temporary one found

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
getBasePath:for the attachment:{attachmentId=49800012, companyId=100193, 
versionUserId=100256, groupId=100264, createDate=Fri Apr 27 17:57:17 GMT 2012, 
modifiedDate=Fri Apr 27 17:57:17 GMT 2012, type_=0, legacy=false, contentState=0, 
embedded=false, fileName=upgrading_ecp_test.docx, dirPath=, summary=4, 
parentClassNameId=0, parentClassPK=0, repositoryId=49800012, version=0.0, size=387476, 
extraData=, locale=, verslyUUID_MSB=0, verslyUUID_LSB=0}the path determined is 
:Post/49800012/

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImmpl::addAttachment(attachment,userId): basePath= Post/49800012/

Apr 27 17:57:17 quad.example.com quad[]: INFO  [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImmpl::addAttachment(attachment,userId): commit phase: add default 
version

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImpl : calling tagDocumentForVersly before addFile()

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
property=versly.office.extensions value:.docx,.xlsx,.pptx

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
extension[i]:.docx

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: Got 
an office extension document:upgrading_ecp_test.docx

Apr 27 17:57:17 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
verslyData.loading file:upload_00000001.docx @ Fri Apr 27 17:57:17 GMT 2012

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
verslyData.load file completed upload_00000001.docx in Fri Apr 27 17:57:21 GMT 2012

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
tagDocumentForVersly :  document before tagging[VerslyData: version=1 
contentId=c2d54b4d-4537-465e-9080-67771e15dd65 
spaceId=c2d54b4d-4537-465e-9080-67771e15dd65 localModificationId=null 
lastModifiedBy=Prasad Velagaleti lastModified=2012-04-18T20:23:00Z creator=Prasad 
Velagaleti created=2012-04-18T20:23:00Z app=Microsoft Macintosh Word appVersion=14.0000 
company=Cisco customProps={{assetId=0, repositoryId=46363836}}]

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
spaced Id : 
c2d54b4d-4537-465e-9080-67771e15dd65contentId:c2d54b4d-4537-465e-9080-67771e15dd65

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
verslyData.storing file:upload_00000001.docx started @ Fri Apr 27 17:57:21 GMT 2012

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
verslyData.storing file:upload_00000001.docx started @ Fri Apr 27 17:57:21 GMT 2012

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
verslyData.storing file:upload_00000001.docx completed @ Fri Apr 27 17:57:21 GMT 2012

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
tagDocumentForVersly :  document after updating.[VerslyData: version=1 
contentId=d5c1fde1-33a5-46f2-9801-314867966e0d 
spaceId=d5c1fde1-33a5-46f2-9801-314867966e0d localModificationId=null 
lastModifiedBy=Prasad Velagaleti lastModified=2012-04-18T20:23:00Z creator=Prasad 
Velagaleti created=2012-04-18T20:23:00Z app=Microsoft Macintosh Word appVersion=14.0000 
company=Cisco customProps={{assetId=0, repositoryId=49800012}}]

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: Saved 
versly data done.[VerslyData: version=1 contentId=d5c1fde1-33a5-46f2-9801-314867966e0d 
spaceId=d5c1fde1-33a5-46f2-9801-314867966e0d localModificationId=null 
lastModifiedBy=Prasad Velagaleti lastModified=2012-04-18T20:23:00Z creator=Prasad 
Velagaleti created=2012-04-18T20:23:00Z app=Microsoft Macintosh Word appVersion=14.0000 
company=Cisco customProps={{assetId=0, repositoryId=49800012}}]

Apr 27 17:57:21 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImmpl::addAttachment(attachment,userId): update attachment in db 
with attachment= {attachmentId=49800012, companyId=100193, versionUserId=100256, 
groupId=100264, createDate=Fri Apr 27 17:57:17 GMT 2012, modifiedDate=Fri Apr 27 17:57:17 
GMT 2012, type_=0, legacy=false, contentState=0, embedded=false, 
fileName=upgrading_ecp_test.docx, dirPath=, summary=4, parentClassNameId=0, 
parentClassPK=0, repositoryId=49800012, version=1.0, size=387476, extraData=, locale=, 
verslyUUID_MSB=-3043872729449806094, verslyUUID_LSB=-7493654117922476531}

Once the user saves the post, you should see the following debug messages where VerslyUUID_MSB and VerslyUUID_LSB (the tagged information before) will be visible on the attachment:

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImpl:addAttachment:{attachmentId=49800012, companyId=100193, 
versionUserId=100256, groupId=100264, createDate=Fri Apr 27 17:57:17 GMT 2012, 
modifiedDate=Fri Apr 27 17:57:17 GMT 2012, type_=0, legacy=false, contentState=0, 
embedded=false, fileName=upgrading_ecp_test.docx, dirPath=, summary=4, 
parentClassNameId=100060, parentClassPK=4800002, repositoryId=49800012, version=1.0, 
size=387476, extraData=, locale=en_US, verslyUUID_MSB=-3043872729449806094, 
verslyUUID_LSB=-7493654117922476531}

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImpl:addAttachment: associated with asset

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: Enter 
AttachmentLocalServiceImmpl::addDocumentAttachment(attachment,userId)

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]:  
AttachmentLocalServiceImmpl::addDocumentAttachment(attachment,userId): asset of attachment 
found

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
getLatestTempAttachment:companyId 100193   fileName:upgrading_ecp_test.docx 
TemporaryAttachment:userId100256

Apr 27 18:07:00 quad.example.com quad[]: INFO  [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImpl::addAttachment(attachment,userId): commit phase: latest ver= 
1.0

Apr 27 18:07:00 quad.example.com quad[]: INFO  [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImmpl::addAttachment(attachment,userId): commit phase of temporary 
attachment= upgrading_ecp_test.docx

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
getBasePath:for the attachment:{attachmentId=49800012, companyId=100193, 
versionUserId=100256, groupId=100264, createDate=Fri Apr 27 17:57:17 GMT 2012, 
modifiedDate=Fri Apr 27 17:57:17 GMT 2012, type_=0, legacy=false, contentState=0, 
embedded=false, fileName=upgrading_ecp_test.docx, dirPath=, summary=4, 
parentClassNameId=100060, parentClassPK=4800002, repositoryId=49800012, version=1.0, 
size=387476, extraData=, locale=en_US, verslyUUID_MSB=-3043872729449806094, 
verslyUUID_LSB=-7493654117922476531}the path determined is :Post/49800012/

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_EVENTING] - [TP-Processor47]: Sending 
event ATTACHMENT_UPLOAD

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_EVENTING] - [TP-Processor47]: Event 
content for event: ATTACHMENT_UPLOAD: 
{"attachmentId":49800012,"attachmentName":"upgrading_ecp_test.docx","class":"com.cisco.ecp
.vdl.event.model.impl.attachment.AttachmentUploadEvent","classNameId":100060,"classPK":480
0002,"clientIp":0,"communityId":100264,"companyId":100193,"eventCreatorFirstName":"Test","
eventCreatorMedium1PortraitId":32000035,"eventCreatorMedium2PortraitId":32000036,"eventCre
atorMedium3PortraitId":32000037,"eventCreatorName":"Test 
Test","eventCreatorScreenName":"test","eventCreatorSmallPortraitId":32000034,"eventCreator
UserId":100256,"eventCreatorUtil":null,"eventTime":1335550020075,"eventType":"ATTACHMENT_U
PLOAD","excludes":null,"includes":null,"quadServerIp":0,"size":387476,"versionId":1.0}

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_EVENTING] - [TP-Processor47]: 
Finished sending event ATTACHMENT_UPLOAD for 4800002

Apr 27 18:07:00 quad.example.com quad[]: DEBUG [QUAD_ATTACHMENT] - [TP-Processor47]: 
AttachmentLocalServiceImmpl::addAttachment(attachment,userId): update attachment in db 
with attachment= {attachmentId=49800012, companyId=100193, versionUserId=100256, 
groupId=100264, createDate=Fri Apr 27 17:57:17 GMT 2012, modifiedDate=Fri Apr 27 17:57:17 
GMT 2012, type_=0, legacy=false, contentState=0, embedded=false, 
fileName=upgrading_ecp_test.docx, dirPath=, summary=1, parentClassNameId=100060, 
parentClassPK=4800002, repositoryId=49800012, version=1.0, size=387476, extraData=, 
locale=en_US, verslyUUID_MSB=-3043872729449806094, verslyUUID_LSB=-7493654117922476531}

Client Side Logs of the Shared Changes Feature

These messages appear when the user opens a document and connection to the XMPP server is established:

2012-04-18 15:43:44 [p:10416] [t:1] 
[Cisco.Office.AbstractAddIn.AbstractOfficeObjectWatcher`2[TApplication,TOfficeObject]] 
[Trace] - OfficeApplication_WindowActivate - C:\Users\shrmohan\Downloads\QFO.docx

2012-04-18 15:43:45 [p:10416] [t:4] [Cisco.Office.Sidebar.Client.ConnectionManager] [Info] 
- Trying to reconnect

2012-04-18 15:43:45 [p:10416] [t:4] [Cisco.Office.Sidebar.Client.XmppClient] [Info] - 
Reconnecting XMPP

2012-04-18 15:43:45 [p:10416] [t:4] [Cisco.Office.Sidebar.Client.XmppClient] [Info] - 
IsRunning was False

2012-04-18 15:43:45 [p:10416] [t:4] [Cisco.Office.Sidebar.Client.XmppClient] [Trace] - 
Closing XMPP connection

The user then makes edits to the document and clicks "Share Changes" to upload their changes to Quad, resulting in these messages:

2012-04-18 15:43:46 [p:10416] [t:9] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - [1] Modification 
change detected in LocalModificationCallback via timer. Recording new modification id: 
0ee8aa0e-22f4-47ad-bd6e-8721279f1a05. Detected status: DirtyWithoutModificationId.

2012-04-18 15:43:46 [p:10416] [t:1] [Cisco.Office.Sidebar.Client.SidebarDataContext] 
[Trace] - [Word] Updating content modification status: Dirty. Local mod status: 
DirtyWithModificationId; IsContentStale: False

2012-04-18 15:43:50 [p:10416] [t:7] [Cisco.Office.Sidebar.Client.ConnectionManager] [Info] 
- Trying to reconnect

2012-04-18 15:43:50 [p:10416] [t:7] [Cisco.Office.Sidebar.Client.XmppClient] [Info] - 
Reconnecting XMPP

2012-04-18 15:43:50 [p:10416] [t:7] [Cisco.Office.Sidebar.Client.XmppClient] [Info] - 
IsRunning was False

2012-04-18 15:43:50 [p:10416] [t:7] [Cisco.Office.Sidebar.Client.XmppClient] [Trace] - 
Closing XMPP connection

2012-04-18 15:43:51 [p:10416] [t:11] [Cisco.Office.Sidebar.Client.XmppClient] [Trace] - 
XMPP connection established. Auth: False; SSL: False

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.AuthenticatingRestClient] [Trace] - req 20950175: Get 
http://198.51.100.35/office/api/v1/contents/3b324dd5-bd32-4b6f-acce-efefbdb813ee/metadata.

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.AuthenticatingRestClient] [Trace] - req 20950175 response: 
RestResponse[status:OK, body:{"status":0,"message":"Operation 
succeeded","requestUri":null,"timeStamp":"2012-04-18T15:43:51.261-07:00","data":{"id":"3b3
24dd5-bd32-4b6f-acce-efefbdb813ee","version":{"name":"QFO.docx","id":"00000000-0000-0000-0
000-000000000002","size":8950,"comment":null,"contentType":"application/vnd.openxmlformats
-officedocument.wordprocessingml.document","member":{"shortName":"B Jim","fullName":"B 
Jim","emailAddress":"b@example.com","avatarUrl":"/office/api/v1/users/portraits/154903018"
,"active":true,"url":"/web/b","permissions":["READ","COMMENT","WRITE","ADMIN"],"role":"Adm
in"},"creationDate":"2012-04-18T15:42:46.441-07:00","url":"/c/post_action/get_attachment?p
ostId=200007&postVersionId=1&attachmentId=155400220","diff":null,"contentId":"3b324dd5-bd3
2-4b6f-acce-efefbdb813ee","spaceId":"3b324dd5-bd32-4b6f-acce-efefbdb813ee","mergePolicy":n
ull,"numericVersion":2,"md5":"a20e4bbfb46de075812b0d24124ce085","via":"Unknown","contentSh
ortId":null,"scribdData":null},"creationDate":"2012-04-18T15:42:46.441-07:00","folderId":n
ull,"spaceId":"3b324dd5-bd32-4b6f-acce-efefbdb813ee","lastUpdated":"2012-04-18T15:42:46.44
1-07:00","dateDeleted":null,"shortId":null}}, source:Server]

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.SidebarController] 
[Trace] - [Word] Updating content version banner visibilities. Server: v2, controller: v2

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.SidebarDataContext] 
[Trace] - [Word] Updating content modification status: Dirty. Local mod status: 
DirtyWithModificationId; IsContentStale: False

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.AuthenticatingRestClient] [Trace] - req 61677545: Get 
http://198.51.100.35/office/api/v1/spaces/3b324dd5-bd32-4b6f-acce-efefbdb813ee/members/. 
Request stack: 
Tuple[http://198.51.100.35/office/api/v1/contents/3b324dd5-bd32-4b6f-acce-efefbdb813ee/met
adata,Get,20950175]

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.ContentRepository] 
[Trace] - loaded content version data {"HeadVersion":2} from 
C:\Users\shrmohan\AppData\Local\Cisco\Quad for 
Office\b\stage\3b324dd5-bd32-4b6f-acce-efefbdb813ee-version-info

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.ContentRepository] 
[Trace] - loaded content version data {"HeadVersion":2} from 
C:\Users\shrmohan\AppData\Local\Cisco\Quad for 
Office\b\stage\3b324dd5-bd32-4b6f-acce-efefbdb813ee-version-info

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.Office.WordContentAdapter] [Trace] - content base is current 
(v2) -- promoting client version without merge

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.ContentRepository] 
[Trace] - loaded content version data {"HeadVersion":2} from 
C:\Users\shrmohan\AppData\Local\Cisco\Quad for 
Office\b\stage\3b324dd5-bd32-4b6f-acce-efefbdb813ee-version-info

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - added latch for 
3b324dd5-bd32-4b6f-acce-efefbdb813ee: 47684453

2012-04-18 15:43:51 [p:10416] [t:11] 
[Cisco.Office.Sidebar.Client.AuthenticatingRestClient] [Trace] - req 61677545 response: 
RestResponse[status:OK, body:{"status":0,"message":"Operation 
succeeded","requestUri":null,"timeStamp":"2012-04-18T15:43:51.307-07:00","data":["b@exampl
e.com"]}, source:Server]

2012-04-18 15:43:51 [p:10416] [t:11] 
[Cisco.Office.Sidebar.Client.AuthenticatingRestClient] [Trace] - req 59810769: Get 
http://198.51.100.35/office/api/v1/spaces/3b324dd5-bd32-4b6f-acce-efefbdb813ee/members/b@e
xample.com. Request stack: 
Tuple[http://198.51.100.35/office/api/v1/contents/3b324dd5-bd32-4b6f-acce-efefbdb813ee/met
adata,Get,20950175], 
Tuple[http://198.51.100.35/office/api/v1/spaces/3b324dd5-bd32-4b6f-acce-efefbdb813ee/membe
rs/,Get,61677545]

2012-04-18 15:43:51 [p:10416] [t:1] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - released and 
removed latch for 3b324dd5-bd32-4b6f-acce-efefbdb813ee: 47684453

2012-04-18 15:43:51 [p:10416] [t:11] 
[Cisco.Office.Sidebar.Client.AuthenticatingRestClient] [Trace] - req 59810769 response: 
RestResponse[status:OK, body:{"status":0,"message":"Operation 
succeeded","requestUri":null,"timeStamp":"2012-04-18T15:43:51.339-07:00","data":{"shortNam
e":"B Jim","fullName":"B 
Jim","emailAddress":"b@example.com","avatarUrl":"/office/api/v1/users/portraits/154903018"
,"active":true,"url":"/web/b","permissions":["READ","COMMENT","WRITE","ADMIN"],"role":"Adm
in"}}, source:Server]

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - waiting for latch 
47684453

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - added latch for 
3b324dd5-bd32-4b6f-acce-efefbdb813ee: 44248072

2012-04-18 15:43:51 [p:10416] [t:1] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - released and 
removed latch for 3b324dd5-bd32-4b6f-acce-efefbdb813ee: 44248072

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - waiting for latch 
44248072

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.SidebarController] 
[Trace] - [Word] Updating content version banner visibilities. Server: v3, controller: v3

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.SidebarDataContext] 
[Trace] - [Word] Updating content modification status: Dirty. Local mod status: 
DirtyWithModificationId; IsContentStale: False

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.AuthenticatingRestClient] [Trace] - req 7219481: Post 
http://198.51.100.35/office/api/v1/contents/3b324dd5-bd32-4b6f-acce-efefbdb813ee/versions/
3?spaceId=3b324dd5-bd32-4b6f-acce-efefbdb813ee. Body: 
Cisco.Office.RestClient.MultipartRequestData[version:VersionPost[Comment: ], 
data:<application/vnd.openxmlformats-officedocument.wordprocessingml.document>]

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.AuthenticatingRestClient] [Trace] - req 7219481 response: 
RestResponse[status:OK, body:{"status":0,"message":"Operation 
succeeded","requestUri":null,"timeStamp":"2012-04-18T15:43:51.879-07:00","data":{"id":"3b3
24dd5-bd32-4b6f-acce-efefbdb813ee","shortId":null,"version":"3","headVersion":{"name":"QFO
.docx","id":"00000000-0000-0000-0000-000000000003","size":9020,"comment":null,"contentType
":"application/vnd.openxmlformats-officedocument.wordprocessingml.document","member":{"sho
rtName":"B Jim","fullName":"B 
Jim","emailAddress":"b@example.com","avatarUrl":"/office/api/v1/users/portraits/154903018"
,"active":true,"url":"/web/b","permissions":["READ","COMMENT","WRITE","ADMIN"],"role":"Adm
in"},"creationDate":"2012-04-18T15:43:51.819-07:00","url":"/c/post_action/get_attachment?p
ostId=200007&postVersionId=1&attachmentId=155400221","diff":null,"contentId":"3b324dd5-bd3
2-4b6f-acce-efefbdb813ee","spaceId":"3b324dd5-bd32-4b6f-acce-efefbdb813ee","mergePolicy":n
ull,"numericVersion":3,"md5":null,"via":"Unknown","contentShortId":null,"scribdData":null}
}}, source:Server]

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.ContentRepository] 
[Trace] - loaded content version data {"HeadVersion":2} from 
C:\Users\shrmohan\AppData\Local\Cisco\Quad for 
Office\b\stage\3b324dd5-bd32-4b6f-acce-efefbdb813ee-version-info

2012-04-18 15:43:51 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.ContentVersionInfo] 
[Trace] - stored new content version data {"HeadVersion":3} in 
C:\Users\shrmohan\AppData\Local\Cisco\Quad for 
Office\b\stage\3b324dd5-bd32-4b6f-acce-efefbdb813ee-version-info

2012-04-18 15:43:51 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - added latch for 
3b324dd5-bd32-4b6f-acce-efefbdb813ee: 47088197

2012-04-18 15:43:51 [p:10416] [t:1] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - released and 
removed latch for 3b324dd5-bd32-4b6f-acce-efefbdb813ee: 47088197

2012-04-18 15:43:52 [p:10416] [t:12] 
[Cisco.Office.Sidebar.Client.PollingLocalModificationWatchdog] [Trace] - waiting for latch 
47088197

2012-04-18 15:43:52 [p:10416] [t:12] [Cisco.Office.Sidebar.Client.SidebarDataContext] 
[Trace] - [Word] Updating content modification status: Clean. Local mod status: Clean; 
IsContentStale: False

User Provided Invalid Token or Invalid Credentials

These messages appear when the user has provided invalid token or invalid credentials:

Apr 10 22:49:58 quad.example.com quad[]: ERROR [OFFICE_API] - [TP-Processor45]: login 
failed Apr 10 22:49:58 quad.example.com java.lang.IllegalAccessException

Apr 10 22:49:58 quad.example.com     at 
com.cisco.quad.office.server.LoginUtil.login(LoginUtil.java:104)

Apr 10 22:49:58 quad.example.com     at 
com.cisco.quad.office.server.QuadUserController.login(QuadUserController.java:87)

Apr 10 22:49:58 quad.example.com     at 
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

Apr 10 22:49:58 quad.example.com     at 
sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

Apr 10 22:49:58 quad.example.com     at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

Apr 10 22:49:58 quad.example.com     at java.lang.reflect.Method.invoke(Unknown Source)

Apr 10 22:49:58 quad.example.com     at 
org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(H
andlerMethodInvoker.java:176)

Apr 10 22:49:58 quad.example.com     at 
org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandle
rMethod(AnnotationMethodHandlerAdapter.java:436)

Apr 10 22:49:58 quad.example.com     at 
org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(Annot
ationMethodHandlerAdapter.java:424)

Apr 10 22:49:58 quad.example.com     at 
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:900)

Apr 10 22:49:58 quad.example.com     at 
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:827)

Apr 10 22:49:58 quad.example.com     at 
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882)
expected failure but is harmless, when user has invalid token or invalid credentials:

Open API Logs

This section is organized as follows:

•Message Format

Message Format

Similarly to all Cisco WebEx Social log messages, API log messages follow this format:

<Timestamp> <Log Level> [Class name] - [thread name] - [user screen name] - [session id]: <log message>

The <log message> part has format that is specific to API log messages, as follows:

•For log levels different than TRACE, the format is:

[API] - message text

•For log level TRACE, the format is:

•When capturing an entry into an API method:

>>Class.Method( args ) [

Where Class is the API class name, Method is the method name and args are the arguments that have been passed to the method.

•When capturing an exit from an API method:

< return data >

] Class.method() << <time elapsed>

Where return data is the result from the method execution, Class is the API class name, Method is the method name, and time elapsed is the time spend executing this method.

•When capturing an exception:

< Exception >

] Class.method()

Where Exception is the exception text, Class is the API class name, and Method is the method name.

An example log excerpt follows. Section explanations are included inline in bold:

API entry point

2011-07-31 21:45:05,984 TRACE [auth.servlet.QuadAuthenticationServletFilter] - 
[http-8080-2] - [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>QuadAuthenticationServletFilter.doFilter( 
org.apache.catalina.connector.RequestFacade@4bdc8171, 
org.apache.catalina.connector.ResponseFacade@79b6489f, 
org.apache.catalina.core.ApplicationFilterChain@2e59fd26 ) [

<...lines omitted for brevity...>

2011-07-31 21:45:06,176 DEBUG [common.util.LoginUtil] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
com.cisco.ecp.openapi.common.util.LoginUtil.login() <Login attempt with login 
test@example.com and auth type emailAddress >

<...lines omitted for brevity...>

Announcing successful login

2011-07-31 21:45:06,955 DEBUG [common.util.LoginUtil] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
com.cisco.ecp.openapi.common.util.LoginUtil.login() <Login attempt successful for login 
test@example.com and auth type emailAddress >

.<...lines omitted for brevity...>

HTTP request details

2011-07-31 21:45:06,580 INFO  [common.logging.QuadLoggingJerseyFilter] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] -

=====>

GET http://ws01.example.com/quadopen/api/rest/users/@me/

host                : ws01.example.com

user-agent          : Mozilla/5.0 (Windows NT 6.1; WOW64; rv:10.0.2) Gecko/20100101 
Firefox/10.0.2

accept              : application/json

Accept-Encoding     : gzip, deflate

connection          : keep-alive

authorization       : OAuth 
realm="http%3A%2F%2Fws01.example.com%2Fquadopen%2Fapi%2Frest%2Fusers%2F%40me%2F",oauth_sig
nature_method="HMAC-SHA1",oauth_version="1.0",oauth_nonce="c1JUD2",oauth_timestamp="132987
9921",oauth_consumer_key="34a1c046163e1659c38b4a98c1db61f2c00a1f24",oauth_token="82c60559-
75a1-fb03-67c3-451964144643",oauth_signature="zXHJK%2FAke2q%2F%2BCCk3Im3UizTFNk%3D"

content-type        : application/json

cookie              : GUEST_LANGUAGE_ID=en_US; COOKIE_SUPPORT=true; 
JSESSIONID=B062955A6C15CC6F74029C5355E461BE.ws01.example.comjvm; LOGIN=6368616e646c6572; 
SCREEN_NAME=374b33682f3273465349766e6d45422b5756693537413d3d

content-length      : 0

=====>

Invoking REST handler

2011-07-31 21:45:07,110 TRACE [api.rest.UserRestHandlerImpl] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - >>UserRestHandlerImpl.getUser( 10382, 
@basic,images, com.cisco.ecp.openapi.protocol.model.QueryParameters@799e525a ) [

<...lines omitted for brevity...>

Processors initiate request processing

2011-07-31 21:45:07,111 TRACE [openapi.processor.DefaultProcessorDelegate] - [http-8080-2] 
- [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>DefaultProcessorDelegate.processRequest( 
{co=com.cisco.ecp.openapi.protocol.model.QueryParameters@799e525a, userId=10382, 
_this=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_args=[Ljava.lang.Object;@366ec9d4, 
_target=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_jp=execution(Response com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl.getUser(long, 
String, QueryParameters)), fields=@basic,images} ) [

2011-07-31 21:45:07,112 TRACE [openapi.processor.AbstractProcessorDelegate] - 
[http-8080-2] - [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>AbstractProcessorDelegate.getProcessors() [

2011-07-31 21:45:07,112 TRACE [openapi.processor.AbstractProcessorDelegate] - 
[http-8080-2] - [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
<[com.cisco.ecp.openapi.processor.FieldsSelectorProcessor@79c05dfa, 
com.cisco.ecp.openapi.processor.MetadataSelectorProcessor@445a0688, 
com.cisco.ecp.openapi.processor.RequestFiltersProcessor@7262edc6, 
com.cisco.ecp.openapi.processor.ServerMessageProcessor@3ce89cd5]>

2011-07-31 21:45:07,112 TRACE [openapi.processor.AbstractProcessorDelegate] - 
[http-8080-2] - [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
AbstractProcessorDelegate.getProcessors()<< 0ms

2011-07-31 21:45:07,112 TRACE [openapi.processor.FieldsSelectorProcessor] - [http-8080-2] 
- [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>FieldsSelectorProcessor.processRequest( 
{co=com.cisco.ecp.openapi.protocol.model.QueryParameters@799e525a, userId=10382, 
_this=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_args=[Ljava.lang.Object;@366ec9d4, 
_target=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_jp=execution(Response com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl.getUser(long, 
String, QueryParameters)), fields=@basic,images} ) [

2011-07-31 21:45:07,112 TRACE [openapi.processor.FieldsSelectorProcessor] - [http-8080-2] 
- [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>FieldsSelectorProcessor.getFieldsFromContext( 
{co=com.cisco.ecp.openapi.protocol.model.QueryParameters@799e525a, userId=10382, 
_this=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_args=[Ljava.lang.Object;@366ec9d4, 
_target=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_jp=execution(Response com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl.getUser(long, 
String, QueryParameters)), fields=@basic,images} ) [

2011-07-31 21:45:07,112 TRACE [openapi.processor.Processor] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - >>Processor.getQueryParametersOrNull( 
{co=com.cisco.ecp.openapi.protocol.model.QueryParameters@799e525a, userId=10382, 
_this=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_args=[Ljava.lang.Object;@366ec9d4, 
_target=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_jp=execution(Response com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl.getUser(long, 
String, QueryParameters)), fields=@basic,images} ) [

2011-07-31 21:45:07,113 TRACE [openapi.processor.Processor] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
<com.cisco.ecp.openapi.protocol.model.QueryParameters@799e525a>

2011-07-31 21:45:07,113 TRACE [openapi.processor.Processor] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
Processor.getQueryParametersOrNull()<< 0ms

<...lines omitted for brevity...>

2011-07-31 21:45:07,118 TRACE [openapi.processor.Processor] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - >>Processor.processRequest( 
{co=com.cisco.ecp.openapi.protocol.model.QueryParameters@799e525a, userId=10382, 
_this=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_args=[Ljava.lang.Object;@366ec9d4, 
_target=com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl@53a21d0b, 
_jp=execution(Response com.cisco.ecp.openapi.api.rest.UserRestHandlerImpl.getUser(long, 
String, QueryParameters)), fields=@basic,images} ) [

2011-07-31 21:45:07,118 TRACE [openapi.processor.Processor] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - <null>

2011-07-31 21:45:07,119 TRACE [openapi.processor.Processor] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] Processor.processRequest()<< 0ms

2011-07-31 21:45:07,119 TRACE [openapi.processor.DefaultProcessorDelegate] - [http-8080-2] 
- [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - <null>

2011-07-31 21:45:07,119 TRACE [openapi.processor.DefaultProcessorDelegate] - [http-8080-2] 
- [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
DefaultProcessorDelegate.processRequest()<< 8ms

Request processing completed. Invoking common service.

2011-07-31 21:45:07,119 TRACE [common.service.UserService] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - >>UserService.getUser( 10382 ) [

Calling VDL for data.

2011-07-31 21:45:07,119 TRACE [common.service.BaseService] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - >>BaseService.getVdlUserById( 10382 ) 
[

<...lines omitted for brevity...>

2011-07-31 21:45:07,193 TRACE [common.service.BaseService] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] BaseService.getVdlUserById()<< 73ms

VDL Service returns data. API layer processes the returned data.

<...lines omitted for brevity...>

2011-07-31 21:45:07,737 TRACE [common.service.UserService] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
<com.cisco.ecp.openapi.common.model.UserModel@f08f2a[firstName=Test,lastName=Test,fullName
=Test 
Test,screenName=test,images=[],startWorkHour=-1,endWorkHour=-1,timeZone=America/Los_Angele
s,jobTitle=,friendlyJobTitle=,addresses=[],emails=[com.cisco.ecp.openapi.common.model.Emai
lModel@3e70bcbe[address=test@example.com,primary=true,id=0,resource=http://ws.example.com/
schema/1.0/email]],phones=[],tags=[],id=10382,resource=http://ws.example.com/schema/1.0/us
er]>

2011-07-31 21:45:07,737 TRACE [common.service.UserService] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] UserService.getUser()<< 618ms

Common service returns processed data to handler layer.

2011-07-31 21:45:07,737 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>AbstractRestHandlerImpl.createResponseItems( 
com.cisco.ecp.openapi.common.model.UserModel@f08f2a[firstName=Test,lastName=Test,fullName=
Test 
Test,screenName=test,images=[],startWorkHour=-1,endWorkHour=-1,timeZone=America/Los_Angele
s,jobTitle=,friendlyJobTitle=,addresses=[],emails=[com.cisco.ecp.openapi.common.model.Emai
lModel@3e70bcbe[address=test@example.com,primary=true,id=0,resource=http://ws.example.com/
schema/1.0/email]],phones=[],tags=[],id=10382,resource=http://ws.example.com/schema/1.0/us
er] ) [

2011-07-31 21:45:07,738 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>AbstractRestHandlerImpl.createResponseItem( 
com.cisco.ecp.openapi.common.model.UserModel@f08f2a[firstName=Test,lastName=Test,fullName=
Test 
Test,screenName=test,images=[],startWorkHour=-1,endWorkHour=-1,timeZone=America/Los_Angele
s,jobTitle=,friendlyJobTitle=,addresses=[],emails=[com.cisco.ecp.openapi.common.model.Emai
lModel@3e70bcbe[address=test@example.com,primary=true,id=0,resource=http://ws.example.com/
schema/1.0/email]],phones=[],tags=[],id=10382,resource=http://ws.example.com/schema/1.0/us
er] ) [

2011-07-31 21:45:07,738 TRACE [common.service.MetaService] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - >>MetaService.createMeta( 
com.cisco.ecp.openapi.common.model.UserModel@f08f2a[firstName=Test,lastName=Test,fullName=
Test 
Test,screenName=test,images=[],startWorkHour=-1,endWorkHour=-1,timeZone=America/Los_Angele
s,jobTitle=,friendlyJobTitle=,addresses=[],emails=[com.cisco.ecp.openapi.common.model.Emai
lModel@3e70bcbe[address=test@example.com,primary=true,id=0,resource=http://ws.example.com/
schema/1.0/email]],phones=[],tags=[],id=10382,resource=http://ws.example.com/schema/1.0/us
er] ) [

<...lines omitted for brevity...>

2011-07-31 21:45:07,740 TRACE [common.service.MetaService] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - <null>

2011-07-31 21:45:07,741 TRACE [common.service.MetaService] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] MetaService.createMeta()<< 2ms

2011-07-31 21:45:07,741 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
<com.cisco.ecp.openapi.protocol.model.ResponseItem@3021ef0d>

2011-07-31 21:45:07,741 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
AbstractRestHandlerImpl.createResponseItem()<< 3ms

2011-07-31 21:45:07,742 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
<com.cisco.ecp.openapi.protocol.model.ResponseItems@3d5572b>

2011-07-31 21:45:07,742 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
AbstractRestHandlerImpl.createResponseItems()<< 5ms

2011-07-31 21:45:07,742 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - >>AbstractRestHandlerImpl.ok( 
com.cisco.ecp.openapi.protocol.model.ResponseItems@3d5572b ) [

2011-07-31 21:45:07,745 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
<com.sun.jersey.core.spi.factory.ResponseImpl@486090fa>

2011-07-31 21:45:07,745 TRACE [api.rest.AbstractRestHandlerImpl] - [http-8080-2] - [test] 
- [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] AbstractRestHandlerImpl.ok()<< 
3ms

Handlers return processed data to processors. Processors start processing the response.

2011-07-31 21:45:07,746 TRACE [openapi.processor.DefaultProcessorDelegate] - [http-8080-2] 
- [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>DefaultProcessorDelegate.processResponse( 
com.sun.jersey.core.spi.factory.ResponseImpl@486090fa ) [

<...lines omitted for brevity...>

2011-07-31 21:45:08,081 TRACE [openapi.processor.DefaultProcessorDelegate] - [http-8080-2] 
- [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
<com.sun.jersey.core.spi.factory.ResponseImpl@48362efe>

2011-07-31 21:45:08,081 TRACE [openapi.processor.DefaultProcessorDelegate] - [http-8080-2] 
- [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
DefaultProcessorDelegate.processResponse()<< 335ms

2011-07-31 21:45:08,081 TRACE [common.util.RequestContextThreadLocal] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>RequestContextThreadLocal.unset() [

2011-07-31 21:45:08,081 TRACE [common.util.RequestContextThreadLocal] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - <null>

2011-07-31 21:45:08,081 TRACE [common.util.RequestContextThreadLocal] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
RequestContextThreadLocal.unset()<< 0ms

2011-07-31 21:45:08,081 TRACE [api.rest.UserRestHandlerImpl] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
<com.sun.jersey.core.spi.factory.ResponseImpl@48362efe>

2011-07-31 21:45:08,081 TRACE [api.rest.UserRestHandlerImpl] - [http-8080-2] - [test] - 
[C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] UserRestHandlerImpl.getUser()<< 
971ms

HTTP response details

2011-07-31 21:45:08,081 INFO  [common.logging.QuadLoggingJerseyFilter] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] -

<=====

STATUS 200 OK

Content-Type        : application/json

Content-Encoding    : gzip

{"statusCode":200,"startIndex":0,"itemsPerPage":1,"totalResults":0,"filtered":false,"sorte
d":false,"entry":[{"data":{"addresses":[],"emails":[{"id":21010003,"resource":"http://ws.e
xample.com/schema/1.0/email","address":"vishal@ws.example.com","primary":true},{"id":0,"re
source":"http://ws.example.com/schema/1.0/email","address":"vveda@ws.example.com","primary
":false}],"endWorkHour":-1,"firstName":"Vishal","friendlyJobTitle":"","fullName":"Vishal 
Veda","id":310003,"images":[{"image":{"id":310058,"resource":"","size":1272,"published":0,
"updated":1327177505058,"fileName":null,"mimeType":"jpg","author":null,"uri":"/image/user_
portrait?img_id=310058&t=1327177505058","height":102,"width":102},"sizeType":"large"},{"im
age":{"id":310062,"resource":"","size":1531,"published":0,"updated":1329527064801,"fileNam
e":null,"mimeType":"jpg","author":null,"uri":"/image/user_portrait?img_id=310062&t=1329527
064801","height":60,"width":60},"sizeType":"medium2"},{"image":{"id":310060,"resource":"",
"size":867,"published":0,"updated":1329527064761,"fileName":null,"mimeType":"jpg","author"
:null,"uri":"/image/user_portrait?img_id=310060&t=1329527064761","height":25,"width":25},"
sizeType":"small"},{"image":{"id":310061,"resource":"","size":994,"published":0,"updated":
1329527064781,"fileName":null,"mimeType":"jpg","author":null,"uri":"/image/user_portrait?i
mg_id=310061&t=1329527064781","height":33,"width":33},"sizeType":"medium1"}],"jobTitle":""
,"lastName":"Veda","manager":{"firstName":"Vishal","fullName":"Vishal 
Veda","id":310003,"images":null,"jobTitle":"","lastName":"Veda","resource":"http://ws.exam
ple.com/schema/1.0/manager","screenName":"vveda"},"phones":[{"id":21010004,"resource":"htt
p://ws.example.com/schema/1.0/phone","primary":false,"number":"+1-555-222-6666","extension
":"","type":"business"},{"id":21010005,"resource":"http://ws.example.com/schema/1.0/phone"
,"primary":true,"number":"555-111-8888","extension":"1234","type":"business"}],"resource":
"http://ws.example.com/schema/1.0/user","screenName":"vveda","startWorkHour":-1,"tags":[],
"timeZone":"America/Los_Angeles"}}],"serverMessages":null}

<=====

2011-07-31 21:45:08,239 TRACE [auth.servlet.UserPermissionServletFilter] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - <null>

Response processing completed.

2011-07-31 21:45:08,239 TRACE [auth.servlet.UserPermissionServletFilter] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
UserPermissionServletFilter.doFilter()<< 1,221ms

2011-07-31 21:45:08,239 TRACE [auth.servlet.QuadAuthenticationServletFilter] - 
[http-8080-2] - [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - <null>

2011-07-31 21:45:08,239 TRACE [auth.servlet.QuadAuthenticationServletFilter] - 
[http-8080-2] - [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
QuadAuthenticationServletFilter.callChain()<< 1,222ms

2011-07-31 21:45:08,239 TRACE [auth.servlet.QuadAuthenticationServletFilter] - 
[http-8080-2] - [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - <null>

2011-07-31 21:45:08,239 TRACE [auth.servlet.QuadAuthenticationServletFilter] - 
[http-8080-2] - [test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
QuadAuthenticationServletFilter.doFilter()<< 2,255ms

2011-07-31 21:45:08,240 TRACE [common.util.RequestContextThreadLocal] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - 
>>RequestContextThreadLocal.unset() [

2011-07-31 21:45:08,240 TRACE [common.util.RequestContextThreadLocal] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - <null>

2011-07-31 21:45:08,240 TRACE [common.util.RequestContextThreadLocal] - [http-8080-2] - 
[test] - [C57D705B208B92CDFD81991173B34914.quadjvm1]: [API] - ] 
RequestContextThreadLocal.unset()<< 0ms

Response is sent to the client

Click to Call and Click to Chat Logs

This section is organized as follows:

•User Clicks to Call

•User Clicks to Chat

User Clicks to Call

These messages appear in the browser's console when the user click to call another user and Cisco Jabber has been selected as preferred client:

placing a call to user[ 7910001 ] at number [ +15559991130]

[VideoTools] Placing a call to +15559991130 via an external call client.

where 7910001 and +15559991130 are replaced with the corresponding user ID and phone number.

These messages appear in the browser's console when the user click to call another user and the built-in client has been selected as preferred client:

placing a call to user[ 7910001 ] at number [ +15559991130] Logger.js:82

[VideoTools] Placing a call to +15559991130 via the build-in plugin.

where 7910001 and +15559991130 are replaced with the corresponding user ID and phone number.

User Clicks to Chat

These messages appear in the browser's console when the user click to chat with another user and Cisco Ja bber has been selected as preferred client:

ChatDebug - Chat.js/startChatScreenName: Starting chat via an external chat client with 
moore

where moore is replaced with the corresponding user screen name.

These messages appear in the browser's console when the user click to chat with another user and the built-in client has been selected as preferred client:

ChatDebug - ChatService.js/startChatSession(): IntegrationId= moore@example.com

where moore@example.com is replaced with the corresponding user integration ID (email).

Email Notifications About Announcements and Alerts

This section is organized as follows:

•AnnouncementsMainJob Started

•Annoucement/Alert Subject to Email Notification is Found

•Announcement/Alert Pushed to MQ and DB Status Updated

•Consumer Retrieves Event from Queue

•Email Successfully Prepared

•SMTP Transportation Begins for Email

•Email Message Sent Successfully

•Generation of Email Failed

AnnouncementsMainJob Started

These messages appear on each worker.digestscheduler.announcements.mainJobRepeatInterval interval. They denote normal operation:

TRACE [announcements.jobs.MainJob] - [QuartzSchedulerEngineInstanceW_Worker-3] - [] - []: 
AnnouncementsMainJob started at Wed Mar 20 13:24:04 GMT 2013

TRACE [announcements.jobs.MainJob] - [QuartzSchedulerEngineInstanceW_Worker-3] - [] - []: 
The MainJob's name is 5cbebadd-8fa7-413c-bc7d-cda3d1577ba6

Annoucement/Alert Subject to Email Notification is Found

These messages appear when an annoucement or alert that is subject to email notification is found:

INFO  [scheduler.util.UniqueRandomNumbersGenerator] - 
[QuartzSchedulerEngineInstanceW_Worker-2] - [] - []: UniqueRandomNumbersGenerator.next = 
2319202587

DEBUG [scheduler.api.SchedulingService] - [QuartzSchedulerEngineInstanceW_Worker-2] - [] - 
[]: Distributor job scheduled: 9cfe40a7-26dd-4a64-8fd6-6086cf05f09c with size 1

DEBUG [announcements.jobs.MainJob] - [QuartzSchedulerEngineInstanceW_Worker-2] - [] - []: 
Created distributor job for announcement: 5310008

INFO  [announcements.jobs.BaseJob] - [QuartzSchedulerEngineInstanceW_Worker-3] - [] - []: 
Job com.cisco.ecp.scheduler.announcements.jobs.DistributorJob: 
<9cfe40a7-26dd-4a64-8fd6-6086cf05f09c>: no memcached record present or the database record 
is newer, using the database record.

DEBUG [announcements.jobs.DistributorJob] - [QuartzSchedulerEngineInstanceW_Worker-3] - [] 
- []: No result in transient info storage for announcement: 5310008

INFO  [scheduler.util.UniqueRandomNumbersGenerator] - 
[QuartzSchedulerEngineInstanceW_Worker-3] - [] - []: UniqueRandomNumbersGenerator.next = 
3861783704

INFO  [scheduler.util.UniqueRandomNumbersGenerator] - 
[QuartzSchedulerEngineInstanceW_Worker-3] - [] - []: UniqueRandomNumbersGenerator.next = 
1798206359

(... The above lines are repeated for each 
worker.outbound.announcement.job.recipient.limit group of recipients. Use the number (e.g. 
1798206359) to trace the event...)

DEBUG [scheduler.api.SchedulingService] - [QuartzSchedulerEngineInstanceW_Worker-3] - [] - 
[]: Bulk job scheduled: 5833ea08-60fe-4f63-bc66-5a538580efff with size 11

INFO  [announcements.jobs.BaseJob] - [QuartzSchedulerEngineInstanceW_Worker-5] - [] - []: 
Job com.cisco.ecp.scheduler.announcements.jobs.BulkJob: 
<5833ea08-60fe-4f63-bc66-5a538580efff>: no memcached record present or the database record 
is newer, using the database record.

Announcement/Alert Pushed to MQ and DB Status Updated

These messages appear when the announcement or alert is pushed to the message queue and its database record is created.

DEBUG [announcements.jobs.BulkJob] - [QuartzSchedulerEngineInstanceW_Worker-5] - [] - []: 
Processing info record 1798206359. Status = PENDING

DEBUG [announcements.jobs.BulkJob] - [QuartzSchedulerEngineInstanceW_Worker-5] - [] - []: 
Transient info record updated successfully

DEBUG [announcements.jobs.BulkJob] - [QuartzSchedulerEngineInstanceW_Worker-5] - [] - []: 
Announcement sent successfully.

Consumer Retrieves Event from Queue

These messages appear when the Consumer retrieves the event from the queue and starts preparing the email.

DEBUG [outbound.amqp.AnnouncementConsumerAction] - [pool-62-thread-2] - [] - []: An 
announcement notification message received. Message: [B@efb86c0

DEBUG [outbound.amqp.AnnouncementConsumerAction] - [pool-62-thread-2] - [] - []: Processed 
announcement notification message for announcement: 5310008

DEBUG [outbound.template.TemplateEngineImpl] - [pool-62-thread-1] - [] - []: Template path 
for event with ID '3723bf89-4127-4e18-9928-75ee97b42983':alerts_notification.vm

TRACE [outbound.cache.AnnouncementTemplateCache] - [pool-62-thread-2] - [] - []: Templated 
announcement : 5310008 not found in cache

DEBUG [outbound.template.TemplateEngineImpl] - [pool-62-thread-2] - [] - []: Start 
processing the template for event with ID: 568e3d90-e7ce-4bc7-b4ae-4690a14a18e2

Email Successfully Prepared

These messages appear when the email has been successfully prepared and is ready for transportation:

DEBUG [outbound.template.TemplateEngineImpl] - [pool-62-thread-1] - [] - []: Template for 
event with ID '3723bf89-4127-4e18-9928-75ee97b42983' processed successfully. The generated 
content is: <html>#012<head>#012</head>#012<body style="background-color: #EAEDED; margin: 
0px; padding: 0px;" alink="#0086C0" link="#0086C0" vlink="#0086C0" bgcolor="#EAEDED">#012    
<table cellpadding="0" cellspacing="0" align="center" width="570" bgcolor="#ffffff" 
border="0">#012        <tbody>#012            <tr height="15" bgcolor="#EAEDED">#012                
<td colspan="4"></td>#012            </tr>#012            <tr bgcolor="#0096eb">#012                
<td><img src="cid:...

Mar 20 13:22:05 worker.example.com ...digest_images_01.gif" /></td>#012                <td 
bgcolor="#0096eb" colspan="2" dir="ltr" width="543">#012                    <table>#012                        
<tr>#012                            <td width="511">#012                                
<font color="#ffffff" size="3" face="arial">#012                                                                            
WebEx Social Announcement#012                                                                    
</font>#012                            </td>#012                            <td 
width="32"><img src="cid:digest_images_ltr_03.jpg" /></td>#012                        
</tr>#012                    </table>#012     ...

(... The message body is dumped here in multiple log lines...)

Mar 20 13:22:05 worker.example.com ...#012<tr bgcolor="#EAEDED">#012    <td colspan="4" 
dir="ltr">#012        <table cellpadding="0" cellspacing="0" border="0">#012            
<tr>#012                <td width="20">&nbsp;</td>#012                <td width="50"  
align="left" ><img src="cid:images_logo.gif" alt='Cisco' width="50" /></td>#012                
<td width="12">&nbsp;</td>#012                <td width="481"  align="left"  
valign="bottom"><font color="#666666" size="1" face="arial">&copy; 2012 Cisco Systems, 
Inc. All rights reserved.</font></td>#012                <td width="20">&nbsp;</td>#012            
</tr>#012        </table>#012    </td>#012</tr>#012#012            </tbody>#012        
</table>#012    </body>#

TRACE [outbound.cache.AnnouncementTemplateCache] - [pool-62-thread-1] - [] - []: Adding to 
cache templated announcement: 5310008

DEBUG [mail.mime.SMTPHeadersInstantUtil] - [pool-62-thread-1] - [] - []: Start generating 
SMTP headers for event with ID: 3723bf89-4127-4e18-9928-75ee97b42983

DEBUG [mail.mime.SMTPHeadersInstantUtil] - [pool-62-thread-1] - [] - []: [Message-ID] 
Header: <quad-a914032d293a40b2bc7215c7fd2f123d-10254-1363785725295@aquila.com>

DEBUG [mail.mime.SMTPHeadersInstantUtil] - [pool-62-thread-1] - [] - []: [Date] Header: 
Mar 20, 2013

DEBUG [mail.mime.SMTPHeadersInstantUtil] - [pool-62-thread-1] - [] - []: [Subject] Header: 
General Announcement

DEBUG [mail.mime.SMTPHeadersInstantUtil] - [pool-62-thread-1] - [] - []: [From] Header: 
Cisco WebEx Social <support@aquila.com>

DEBUG [mail.mime.SMTPHeadersInstantUtil] - [pool-62-thread-1] - [] - []: [Sender] Header: 
Cisco WebEx Social <support@aquila.com>

SMTP Transportation Begins for Email

These messages appear when the actual SMTP transporation begins for an email message.

DEBUG [sender.mail.MailTransport] - [pool-62-thread-2] - [] - []: SMTP configuration being 
used: protocol: smtp, host: worker.example.com, port: 25, user: null

Email Message Sent Successfully

These messages appear when the email message has been sent successfully.

DEBUG [sender.mail.MailSender] - [pool-62-thread-1] - [] - []: successfully send email for 
event 1a729a88-e94c-4b4b-8b64-21bc3c684efd

Generation of Email Failed

These messages appear on WARN logging level in warn.log when the the email message couldn't be created. No email will be sent in this case.

ERROR [velocity.app.VelocityEngine] - [pool-62-thread-2] - [] - []: ResourceManager : 
unable to find resource 'alerts_notification.vm' in any resource loader.

ERROR [outbound.amqp.AnnouncementConsumerAction] - [pool-62-thread-2] - [] - []: Non 
retryable exception has occured for message: [B@7d9f1f64

Synthetic Monitor

When Synthetic Monitoring logs a failure, it will write details into the messages log for the App Server node where the failure occurred. Consider this example where the Synthetic Monitoring test was disrupted because the App Server was restarted:

Apr  4 00:30:01 localhost.localdomain monitor[31730]: ERROR POST 
https://localhost/quadopen/oauth/xauth_access_token response is 503

Apr  4 00:30:01 localhost.localdomain monitor[31730]: ERROR Synthetic: Error: POST 
operation on uri: https://localhost/quadopen/oauth/xauth_access_token: <!DOCTYPE HTML 
PUBLIC "-//IETF//DTD HTML 2.0//EN">#012<html><head>#012<title>503 Service Temporarily 
Unavailable</title>#012</head><body>#012<h1>Service Temporarily Unavailable</h1>#012<p>The 
server is temporarily unable to service your#012request due to maintenance downtime or 
capacity#012problems. Please try again later.</p>#012</body></html>

Centralized Credentials Management (Master Password)

When a service (VoiceMail in example) uses the master account to authenticate a user but the credentials are wrong leading to master account lock out, you can see these logs:

2013-06-10 11:39:42,727 DEBUG [service.impl.PaPassLocalServiceImpl] - [http-8080-2] - 
[ivxie] - [B4582D507A96A72A7E49FAE5154C7196]: Updated credentials for userId: 31710010 for 
Service: VoiceMail to -1

Consequently when any service tries to use the master account you can see log lines like these:

2013-06-10 11:39:42,823 DEBUG [service.impl.PaPassLocalServiceImpl] - [http-8080-3] - 
[ivxie] - [B4582D507A96A72A7E49FAE5154C7196]: Check Credentials for user =>31710010 and 
service => VoiceMail

2013-06-10 11:39:42,827 DEBUG [service.impl.PaPassLocalServiceImpl] - [http-8080-3] - 
[ivxie] - [B4582D507A96A72A7E49FAE5154C7196]: Credentials for user =>31710010 and service 
=> VoiceMail are INACTIVE

Session Centralization

This section is organized as follows:

•Normal startup

•Issues Enforcing The Sessions Limitation

Normal startup

When Tomcat starts up the following log messages appear in the App Server log if session centralization has been configured. If you do not see these messages then you are using normal sessions and sessions are not being stored in memcached. Session limitation cannot be enforced if this is the case.

The log messages also show different parameters configured for session centralization. For example 198.51.100.35 and 198.51.100.36 are the memcached server nodes.

Jun 11 22:25:39 appserver.example.com quad[]: INFO  
[session.management.MemcachedSessionService] - [main] - [] - []: MemcachedSessionService 
starts initialization... (configured nodes definition 
n1:198.51.100.35:11211,n2:198.51.100.36:11211, failover nodes null)

Jun 11 22:25:40 appserver.example.com quad[]: INFO  
[session.management.RequestTrackingHostValve] - [main] - [] - []: Setting ignorePattern to 
.*\.(ico|png|gif|jpg|css|js)$

Jun 11 22:25:40 appserver.example.com quad[]: INFO  
[session.management.MemcachedSessionService] - [main] - [] - []: Setting lockingMode to 
null

Jun 11 22:25:40 appserver.example.com quad[]: INFO  
[session.management.MemcachedSessionService] - [main] - [] - []: Creating transcoder 
factory com.cisco.ecp.portal.kernel.session.management.JavaSerializationTranscoderFactory

Jun 11 22:25:40 appserver.example.com quad[]: INFO  
[session.management.MemcachedSessionService] - [main] - [] - []: MemcachedSessionService 
finished initialization, sticky true, operation timeout 1000, with node ids [n1, n2] and 
failover node ids []

Issues Enforcing The Sessions Limitation

These log messages may appear when there are issues enforcing the number of sessions limitation.

Jun 11 22:25:39 appserver.example.com quad[]: INFO  
[session.management.MemcachedSessionService] - [main] - [] - []: MemcachedSessionService 
starts initialization... (configured nodes definition 
n1:198.51.100.35:11211,n2:198.51.100.36:11211, failover nodes null)

Jun 11 22:25:40 appserver.example.com quad[]: INFO

To verify if this is indeed the case, check to see if all the memcached servers are up. If they are but you still see the error, run this command on the affected App Server nodes and look for TCP sessions with the memcached servers:

netstat -an | grep 11211

If you don't see any TCP connections in port 11211, then enable Caching Services debug logging as described in How do I set the log trace levels for Session Centralization/Concurrent Sessions Limitation and what log files to collect? and examine the logs for clues as to what is happening.

Table Of Contents

Logs

Logs Overview

Log Files Stored on the Director by Role

Localy-stored Log Files by Role

Understanding Logs

Monit Logs

Monit Starts Up

Monit Check Failed

Manually Restarting Monit

Resource Overutilization

Purging /opt

Nagios Starts Up/Shuts Down

Common False Positives

Node is No Longer Active/Available but Exists in the Topology

Monit service Not Running on a Node

Chart Data Missing for a Node

Failure: Core Service is Down for an Extended Period of Time

Rsyslog Starts Up/Shuts Down

Rsyslog is Rate Limited

Service is Down

Analytics Service Initialized Successfully

MapReduce Scheduler Logs

Calendar Logs

Getting a Month Worth of Meetings with Configured Domino and WebEx (No Cached Data)

Getting a Month Worth of Meetings with Configured Domino and WebEx (Cached Data)

Getting a Month Worth of Meetings with Configured WebDAV (No Cached Data)

Selecting a Domino Event from the List of Events

Framework Logs

Incorrect Theme ID

Streams Logs

Errors During Interpretation

VDL Backend Debugging

Email Integration Logs

Successfully Sent an Instant Email Notification

Successfully Sent an Email Digest

Problem with Connection to Postfix

No Active SMTP Server or No SMTP Server Defined in Configuration

VTL Syntax Error in Template File

Expected Warning Message in Worker Log

An Email is Sent Following a User Action

Email Sent to a Community or a Discussion Category

Office Plug-in Logs

User Enters Wrong Server URL in Settings

Office Plug-in Has Loaded Successfully

Failed Theme Update Due to Server Error

Failed Theme Update Due to Missing Image

Cisco WebEx Social Call Plug-in Logs

Error in User Configuration

WebEx Social for Office Logs

Client Lists Attachments to a Post

Client Lists Comments to a Post and Adds New Comment

Client Downloads File Successfully

Client Adds New Version of an Attachment

Server Side Logs of the Shared Changes Feature

Client Side Logs of the Shared Changes Feature

User Provided Invalid Token or Invalid Credentials

Open API Logs

Message Format

Click to Call and Click to Chat Logs

User Clicks to Call

User Clicks to Chat

Email Notifications About Announcements and Alerts

AnnouncementsMainJob Started

Annoucement/Alert Subject to Email Notification is Found

Announcement/Alert Pushed to MQ and DB Status Updated

Consumer Retrieves Event from Queue

Email Successfully Prepared

SMTP Transportation Begins for Email

Email Message Sent Successfully

Generation of Email Failed

Synthetic Monitor

Centralized Credentials Management (Master Password)

Session Centralization

Normal startup

Issues Enforcing The Sessions Limitation