Ajcody-Logging: Difference between revisions
Line 601: | Line 601: | ||
[[Category: Community Sandbox]] | [[Category: Community Sandbox]] | ||
[[Category: | [[Category:Logging]] |
Revision as of 18:09, 16 August 2008
Logging
Actual Logging Homepage
Please see Ajcody-Logging
Server
Syslog Items
tail /etc/syslog.conf local0.* -/var/log/zimbra.log auth.* -/var/log/zimbra.log mail.* -/var/log/zimbra.log
Restarting syslog
/etc/init.d/syslog restart
Where's It All Go?
Any stacktrace files will have the process id of the JVM appended to the filename.
In all releases 5.0.x and 4.5.x, this is the main mailbox application log:
- /opt/zimbra/log/mailbox.log
In ZCS 5.0.x, the JVM output log and stacktrace files will be in /opt/zimbra/log/:
- /opt/zimbra/log/zmmailboxd.out (jvm output log)
- /opt/zimbra/log/stacktrace.<pid>
Meaning, changes to /opt/zimbra/conf/log4j.properties.in
This file, /opt/zimbra/conf/log4j.properties.in , also controls where some events are logged to.
Example:
# Appender AUDIT writes to the file "audit.log". log4j.appender.AUDIT=org.apache.log4j.DailyRollingFileAppender log4j.appender.AUDIT.File=/opt/zimbra/log/audit.log log4j.appender.AUDIT.DatePattern='.'yyyy-MM-dd log4j.appender.AUDIT.Append=true log4j.appender.AUDIT.layout=com.zimbra.common.util.ZimbraPatternLayout log4j.appender.AUDIT.layout.ConversionPattern=%d %-5p [%t] [%z] %c{1} - %m%n
Log Rotation and Removal
Please look at the output of your crontab - AS ZIMBRA, look for the "Log pruning" line.
crontab -l
And also the config files for logrotate:
/etc/logrotate.conf
/etc/logrotate.d/zimbra
What's up with all the logs?
Logging page resources:
http://www.zimbra.com/docs/ne/latest/administration_guide/9_Monitoring.14.1.html
http://wiki.zimbra.com/index.php?title=Server_Monitoring
http://wiki.zimbra.com/index.php?title=Monitoring_Zimbra_Servers
http://wiki.zimbra.com/index.php?title=Log_Files
http://wiki.zimbra.com/index.php?title=Unresponsive_Server_Troubleshooting
The Bread And Butter Logs
/opt/zimbra/log/mailbox.log - This log is a mailboxd log4j server log containing the logs from the mailbox server. This includes the mailbox store, LMTP server, IMAP and POP servers, and Index server.
/opt/zimbra/log/zmmailbox.out - Mailstore not coming up and nothing is being logged in mailbox.log, check here for errors.
/var/log/zimbra.log - The Zimbra syslog details the activities of the Zimbra MTA (Postfix, amavisd, antispam, antivirus), Logger, Authentication (cyrus-sasl), and Directory (OpenLDAP). By default LDAP activity is logged to Zimbra.log.
/opt/zimbra/db/data/YOURHOSTNAME.err - This is the message store database error log.
/var/log/messages
Logging Increase
Depending on the ZCS version the below will clear all the per account loggers on zimbra reboot. IMAP is used for these examples.
zmprov aal user@domain.com zimbra.imap debug
zmprov ral user@domain.com zimbra.imap
If you want to do it globally edit /opt/zimbra/conf/log4j.properties.in (add a line at the end that's similar but like log4j.logger.zimbra.imap=DEBUG). No restart of any service is needed.
Log4J Variables
"zimbra.misc" logger. For all events that don't have a specific-catagory.
"zimbra.index" logger. For indexing-related events.
"zimbra.index.lucene" logger. For logging of low-level lucene operations (debug-level only)
"zimbra.searchstat" logger. For logging statistics about what kinds of searches are run
"zimbra.redolog" logger. For redolog-releated events.
"zimbra.lmtp" logger. For LMTP-related events.
"zimbra.smtp" logger. For SMTP-related events.
"zimbra.nio" logger. For NIO-related events.
"zimbra.imap" logger. For IMAP-related events.
"zimbra.imap" logger. For POP-related events.
"zimbra.mailbox" logger. For mailbox-related events.
"zimbra.calendar" logger. For calendar-related events.
"zimbra.im" logger. For instant messaging-related events.
"zimbra.account" logger. For account-related events.
"zimbra.gal" logger. For account-related events.
"zimbra.ldap" logger. For ldap-related events.
"zimbra.security" logger. For security-related events
"zimbra.soap" logger. For soap-related events
"zimbra.test" logger. For testing-related events
"zimbra.sqltrace" logger. For tracing SQL statements sent to the database
"zimbra.dbconn" logger. For tracing database connections
"zimbra.perf" logger. For logging performance statistics
"zimbra.cache" logger. For tracing object cache activity
"zimbra.filter" logger. For filter-related logs.
"zimbra.session" logger. For session- and notification-related logs.
"zimbra.backup" logger. For backup/restore-related logs.
"zimbra.system" logger. For startup/shutdown and other related logs.
"zimbra.sync" logger. For sync client interface logs.
"zimbra.synctrace" logger. For sync client interface logs.
"zimbra.syncstate" logger. For sync client interface logs.
"zimbra.wbxml" logger. For wbxml client interface logs.
"zimbra.extensions" logger. For logging extension loading related info.
"zimbra.zimlet" logger. For logging zimlet related info.
"zimbra.wiki" logger. For wiki and document sharing.
"zimbra.op" logger. Logs server operations
"zimbra.dav" logger. Logs dav operations
"zimbra.io" logger. Logs file IO operations.
"zimbra.datasource" logger. Logs data source operations.
remote management.
public static final Log rmgmt = LogFactory.getLog("zimbra.rmgmt");
"zimbra.webclient" logger. Logs ZimbraWebClient servlet and jsp operations.
"zimbra.scheduler" logger. Logs scheduled task operations.
"zimbra.store" logger. Logs filesystem storage operations.
"zimbra.fb" logger. Logs free/busy operations.
"zimbra.purge" logger. Logs mailbox purge operations.
"zimbra.mailop" logger. Logs changes to items in the mailbox.
Thread Dump To Mailbox.log
Run this command as root
for i in 1 2 3; do /opt/zimbra/libexec/zmmailboxdmgr threaddump; sleep 30; done
Hopefully the zmmailboxd.out will reflect the thread dumps.
A Better Way To Thread Dump?
Usage of the below script:
- $0 FILENAME -dl [-frames #_ stack_frames] [-id REGEXP] [-all]
- $0 FILENAME -dt [-frames #_ stack_frames] [-sort id|state] [-stack REGEXP] [-id REGEXP] [-state REGEXP] [-waiting NUMBER]
- frames: controls the # lines of stack trace included in the output
- id: only include where the id matches REGEXP
- all: include ALL locks (not just ones that other threads are blocked-on)
- sort: controls the order threads are printed out (locks always printed in lock ID order)
- stack: only include threads where the thread's stack output matches REGEXP
- state: only include threads where the thread state (e.g. RUNNABLE) matches REGEXP
- waiting: only inclure threads are blocking other threads
Examples:
- $0 threads.txt -dt -stack MailboxIndex.java -state RUNNABLE -f 20
- -- dumps all RUNNABLE threads with MailboxIndex.java on the stack (1st 20 lines of the stack)
- $0 threads.txt -dt -stack MailboxIndex.java -state RUNNABLE -f 20
- $0 threads.txt -dl -f 0
- -- dumps the list of locks in the system that are blocking at least one thread
- $0 threads.txt -dl -f 0
- $0 threads.txt -dt -f 0 -sort state
- -- dumps a list of all the threads in the system and tells you their run state
- $0 threads.txt -dt -f 0 -sort state
- $0 threads.txt -dt -f 20 -w 1
- -- dumps a list of all the threads in the system that are blocking other threads (quick way to hunt for contention)
- $0 threads.txt -dt -f 20 -w 1
Working Example:
- threadDumpAnalyzer.pl zmmailboxd.out -dl -f 100 ~/Desktop
threadDumpAnalyzer.pl Script
#!/usr/bin/perl -w # # ***** BEGIN LICENSE BLOCK ***** # # Zimbra Collaboration Suite Server # Copyright (C) 2004, 2005, 2006, 2007 Zimbra, Inc. # # The contents of this file are subject to the Yahoo! Public License # Version 1.0 ("License"); you may not use this file except in # compliance with the License. You may obtain a copy of the License at # http://www.zimbra.com/license. # # Software distributed under the License is distributed on an "AS IS" # basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. # # ***** END LICENSE BLOCK ***** # use strict; use warnings; use Getopt::Long; my %locks; # by LockID - hash w/ 'owner','type' my %threads; # by threadId - hash w/ 'state' 'waitingOnLock' my $filename = $ARGV[0]; my ($dumpLocks, $dumpThreads, $searchThreadStack, $searchThreadId, $stackFrames, $sort, $filterByState, $allLocks); my ($waiting); $stackFrames = 10; $sort = "state"; GetOptions( "dl" => \$dumpLocks, "dt" => \$dumpThreads, "frames=s" => \$stackFrames, "sort=s" => \$sort, "id=s" => \$searchThreadId, "state=s" => \$filterByState, "stack=s" => \$searchThreadStack, "waiting=s" => \$waiting, "all" => \$allLocks, ); sub dumpLocks(); sub handleThread(); sub dumpThreads(); sub usage(); sub readFile($); sub getBlockedThreads($); if (!defined $filename) { usage(); } readFile($filename); if (defined $dumpLocks) { dumpLocks(); } elsif (defined $dumpThreads) { dumpThreads(); } else { usage(); } exit(0); sub usage() { my $usage = <<END_OF_USAGE; USAGE: $0 FILENAME -dl [-frames #_ stack_frames] [-id REGEXP] [-all] $0 FILENAME -dt [-frames #_ stack_frames] [-sort id|state] [-stack REGEXP] [-id REGEXP] [-state REGEXP] [-waiting NUMBER] frames: controls the # lines of stack trace included in the output id: only include where the id matches REGEXP all: include ALL locks (not just ones that other threads are blocked-on) sort: controls the order threads are printed out (locks always printed in lock ID order) stack: only include threads where the thread's stack output matches REGEXP state: only include threads where the thread state (e.g. RUNNABLE) matches REGEXP waiting: only inclure threads are blocking other threads Examples: $0 threads.txt -dt -stack MailboxIndex.java -state RUNNABLE -f 20 -- dumps all RUNNABLE threads with MailboxIndex.java on the stack (1st 20 lines of the stack) $0 threads.txt -dl -f 0 -- dumps the list of locks in the system that are blocking at least one thread $0 threads.txt -dt -f 0 -sort state -- dumps a list of all the threads in the system and tells you their run state $0 threads.txt -dt -f 20 -w 1 -- dumps a list of all the threads in the system that are blocking other threads (quick way to hunt for contention) END_OF_USAGE die $usage; } sub mySort($$) { my ($a, $b) = @_; if ($sort eq "state") { my $state1 = $threads{$a}{state}; my $state2 = $threads{$b}{state}; if (!defined $state1) { return 1; } elsif (!defined $state2) { return -1; } return $state1 cmp $state2; } else { return $a cmp $b; } } sub padToWidth($$) { (my $str, my $width) = @_; if (!defined($str)) { $str = ""; } return sprintf "%-".$width.".".$width."s", $str; } sub formatStackTrace($$) { my ($stack, $indent) = @_; my $ret; if ($stackFrames == 0) { return ""; } my $num = $stackFrames; foreach my $line (split /\n/, $stack) { if ($num <= 0) { return $ret; } $ret .= $indent.$line."\n"; $num--; } return $ret; } sub formatLock($) { my $lockId = shift; my $output = "$lockId - "; my $numData = 0; for my $data (keys %{ $locks{$lockId}}) { $output .= " $data="; $output .= $locks{$lockId}{$data}; $numData++; } if ($numData == 0) { $output .= " UNKNOWN"; } return $output; } sub formatThread($) { my $threadId = shift; if (!defined $threadId) { return ""; } my $foo = padToWidth($threadId, 50); if (!defined($foo) || $foo eq "") { $foo = "ASDF"; } my $bar = $threads{$threadId}{state}; if (!defined($bar) || $bar eq "") { $bar = "HJKL"; } my $ret = $foo.$bar."\n"; if (defined $threads{$threadId}{waitingOnLock}) { $ret .= "\tWaiting for: ".formatLock($threads{$threadId}{waitingOnLock})."\n"; } my @blockedThreads = getBlockedThreads($threadId); for my $blockedThread (sort @blockedThreads) { $ret .= "\t$blockedThread is waiting on this thread\n"; } $ret .= formatStackTrace($threads{$threadId}{stack}, "\t "); if ($stackFrames > 0) { $ret .= "\n"; } return $ret; } # given a lockId, return a list of the threads that are blocked on it sub getLockWaiters($) { my $lockId = shift; my @ret; foreach my $threadId ( keys %threads ) { if (defined $threads{$threadId}{waitingOnLock}) { if ($threads{$threadId}{waitingOnLock} eq $lockId) { push @ret, $threadId; } } } return @ret; } sub getLockOwner($) { my $lockId = shift(); if (defined $locks{$lockId}) { if (defined $locks{$lockId}{owner}) { return $locks{$lockId}{owner}; } else { return ""; } } else { return ""; } } # given a threadId, get a list of all other threads that are blocked # on locks it is holding sub getBlockedThreads($) { my $threadId = shift; my @ret; foreach my $lockId ( sort keys %locks ) { if (getLockOwner($lockId) eq $threadId) { # a lock we own my @blockedThreads = getLockWaiters($lockId); foreach my $blockedThread (@blockedThreads) { push @ret, $blockedThread; push @ret, getBlockedThreads($blockedThread); #recurse! } } } return @ret; } sub dumpLocks() { foreach my $lockId ( sort keys %locks ) { my $ret = ""; my $numWaiters = 0; $ret .= "LOCK: $lockId "; for my $data (keys %{ $locks{$lockId}}) { $ret .= "$data="; $ret .= $locks{$lockId}{$data}; $ret .= ", "; } $ret .= "\n"; foreach my $threadId ( keys %threads ) { if (defined $threads{$threadId}{waitingOnLock}) { if ($threads{$threadId}{waitingOnLock} eq $lockId) { $ret .= "\tThread $threadId is waiting for this lock\n"; $numWaiters++; } } } $ret .= formatStackTrace($threads{getLockOwner($lockId)}{stack}, "\t"); if ((!defined $searchThreadId) || ($lockId =~ /$searchThreadId/)) { if ($numWaiters > 0 || defined $allLocks) { if ($stackFrames > 0) { $ret .= "\n"; } print $ret; } } } } sub dumpThreads() { foreach my $threadId ( sort { mySort($a, $b) } keys %threads ) { if (!defined $threadId) { # continue } elsif (defined $searchThreadStack && !($threads{$threadId}{stack} =~ /$searchThreadStack/)) { # continue } elsif (defined $searchThreadId && !($threadId =~ /$searchThreadId/)) { # continue } elsif (defined $filterByState && !($threads{$threadId}{state} =~ /$filterByState/)) { # continue } elsif (defined $waiting && (getBlockedThreads($threadId) < $waiting)) { # continue } else { print formatThread($threadId); } } } sub readFile($) { my $filename = shift; open IN, "<$filename" or die "couldn't open $filename"; my @curThread; while (<>) { chomp; s/\r//g; if ($_ eq "") { if (@curThread) { my $threadId; my @locksHeld; my $waitingOnLock; my $threadState; my $output; my $firstLineState; # 1stline my $line = shift @curThread; $output .= $line."\n"; if ($line =~ /"(.*)"/) { $threadId = $1; if ($line =~/nid=0x[0-9a-f]+\s([a-zA-Z\s\.()]+)/) { $threads{$threadId}{state} = $1; } } else { $threadId = $line; } if ($threadId eq "") { $threadId = "none"; } # 2nd line $line = shift @curThread; if (defined $line) { $output .= $line."\n"; if ($line =~ /State: ([A-Z_]+)/) { $threadState = $1; $threads{$threadId}{state} = $1; } foreach $line (@curThread) { $output .= $line."\n"; if ($line =~ /locked <(0x[0-9a-f]+)>\s?(.*)?/) { push @locksHeld, $1; $locks{$1}{owner} = $threadId; $locks{$1}{type} = $2; } elsif ($line =~ /- waiting to lock <(0x[0-9a-f]+)>/) { $waitingOnLock = $1; $threads{$threadId}{waitingOnLock} = $1; } elsif ($line =~ /- waiting to lock <(0x[0-9a-f]+)>/) { $waitingOnLock = $1; $threads{$threadId}{waitingOnLock} = $1; } } } else { $threads{$threadId}{state} = "unknown"; } $threads{$threadId}{stack} = $output; undef @curThread; } } else { push @curThread, $_; } } close IN; }
Third Party Tools
You could also look at using Splunk and Nagios.
http://www.nagios.org/products/enterprisesolutions/splunk/
Web Client Logging
Debug (SOAP) via Browser
See http://wiki.zimbra.com/index.php?title=Web_Client_URL_Tricks&redirect=no