Cisco WebEx Social Troubleshooting Guide, Release 3.1
Logs
Downloads: This chapterpdf (PDF - 431.0KB) The complete bookPDF (PDF - 2.78MB) | Feedback

Logs

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

Email Plug-in Logs

User Enters Wrong Server URL in Settings

Email Plug-in Has Loaded Successfully

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


Logs


This chapter provides information about log file names and locations as well as other log-related information.

This chapter is organized as follows:

Logs Overview

Log Files Stored on the Director by Role

Localy-stored Log Files by Role

Understanding Logs

Logs Overview

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

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

Message Queue

/opt/cisco/rabbitmq/log/rabbit@<hostname>.log
/opt/cisco/rabbitmq/log/rabbit@<hostname>-sasl.log

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/[ssl*log]
/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

Email Plug-in Logs

Cisco WebEx Social Call Plug-in Logs

WebEx Social for Office Logs

Open API Logs

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]
 
   

Email Plug-in Logs

This section is organized as follows:

User Enters Wrong Server URL in Settings

Email Plug-in Has Loaded Successfully

User Enters Wrong Server URL in Settings

These log messages appear in the email 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:

Email Plug-in Has Loaded Successfully

These log messages appear in the email plug-in log file on the user computer when the email 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.

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