Understanding And Troubleshooting Authentication Log Events

Admin Article

Article Information

This article applies to the following ZCS versions.

ZCS 8.6 Article ZCS 8.6 ZCS 8.5 Article ZCS 8.5 ZCS 8.0 Article ZCS 8.0


Understanding And Troubleshooting Authentication Log Events

Purpose

Understanding And Troubleshooting Authentication Log Events

Resolution

IMAP And Authenticated SMTP [SSL] Example

  • For the examples below, the ZCS server being used has an ip address of 10.137.27.32 .
  • Note, I included the client IP address [10.16.245.217] of the IMAP client and also the -C2 flag for egrep to show 2 lines proceeding and after the match for ip and username. I also trimmed the output using the time I did the initial IMAP setup and used the -F option for grep because of the : character. [ | grep -F 'Jun 4 08:4' ]

Using the test account above, ajcody@ , I configured it to use IMAP [Use SSL option] and authenticated SMTP [SSL and "password" option] with Apple's Mail.App. My initially login creates these authentication events below.

First, to give you a general impression what logs will hold information on a username and the ip address the client is connection from. The -l option for grep/egrep will just list the files names that have a math to the search.

[root@zcs723 log]# egrep -l 'ajcody|10.16.245.217' /opt/zimbra/log/*
/opt/zimbra/log/2013_05_31.trace.log  << Because of my ZWC login session
/opt/zimbra/log/2013_06_04.trace.log  << Because of my ZWC login session
/opt/zimbra/log/access_log.2013-05-31 << Because of my ZWC login session
/opt/zimbra/log/access_log.2013-06-04 << Because of my ZWC login session
/opt/zimbra/log/audit.log
/opt/zimbra/log/mailbox.log

[root@zcs723 log]# egrep -l 'ajcody|10.16.245.217' /var/log/*
## Removed not related matches because I've sshd into the server
/var/log/maillog
/var/log/maillog-20130602
/var/log/messages
/var/log/messages-20130602
/var/log/zimbra.log

Now to see what the events are. In the /opt/zimbra/log/audit.log file we have:

# grep egrep -C2 'ajcody|10.16.245.217' /opt/zimbra/log/audit.log | grep -F 'Jun  4 08:4'
    [cut out prior events]
2013-06-04 08:43:01,943 INFO  [ImapServer-1] [ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  security - cmd=Auth; account=ajcody@zcs723.EXAMPLE.com; protocol=imap;
2013-06-04 08:43:04,031 INFO  [ImapServer-2] [ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  security - cmd=Auth; account=ajcody@zcs723.EXAMPLE.com; protocol=imap;
2013-06-04 08:43:07,078 INFO  [ImapServer-3] [ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  security - cmd=Auth; account=ajcody@zcs723.EXAMPLE.com; protocol=imap;
2013-06-04 08:43:09,437 INFO  [ImapServer-4] [ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  security - cmd=Auth; account=ajcody@zcs723.EXAMPLE.com; protocol=imap;
2013-06-04 08:43:11,645 INFO  [ImapServer-5] [ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  security - cmd=Auth; account=ajcody@zcs723.EXAMPLE.com; protocol=imap;

And in the /var/log/zimbra.log :

[root@zcs723 log]# egrep -C2 'ajcody|10.16.245.217' zimbra.log | grep -F 'Jun  4 08:4'
    [cut out prior events]
Jun  4 08:42:07 zcs723 zmmailboxdmgr[1389]: status requested
Jun  4 08:42:07 zcs723 zmmailboxdmgr[1389]: status OK
Jun  4 08:42:27 zcs723 postfix/smtpd[1487]: connect from unknown[10.16.245.217]
Jun  4 08:42:28 zcs723 postfix/smtpd[1487]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: SSL_accept error from unknown[10.16.245.217]: -1
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: lost connection after STARTTLS from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: disconnect from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: connect from unknown[10.16.245.217]
Jun  4 08:42:31 zcs723 postfix/smtpd[1487]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:31 zcs723 postfix/smtpd[1487]: Anonymous TLS connection established from unknown[10.16.245.217]: 
  TLSv1 with cipher AES128-SHA (128/128 bits)
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: connect from unknown[10.16.245.217]
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: Anonymous TLS connection established from unknown[10.16.245.217]: 
  TLSv1 with cipher AES128-SHA (128/128 bits)
--
Jun  4 08:42:33 zcs723 saslauthd[8077]: auth_zimbra: ajcody auth OK
Jun  4 08:42:34 zcs723 postfix/smtpd[1497]: disconnect from unknown[10.16.245.217]
Jun  4 08:42:34 zcs723 postfix/smtpd[1487]: lost connection after EHLO from unknown[10.16.245.217]
Jun  4 08:42:34 zcs723 postfix/smtpd[1487]: disconnect from unknown[10.16.245.217]
Jun  4 08:43:01 zcs723 zmmailboxdmgr[1583]: status requested
Jun  4 08:43:01 zcs723 zmmailboxdmgr[1583]: status OK
--
Jun  4 08:45:08 zcs723 zmmailboxdmgr[2353]: status requested
Jun  4 08:45:08 zcs723 zmmailboxdmgr[2353]: status OK
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max connection rate 3/60s for 
  (smtp:10.16.245.217) at Jun  4 08:42:32
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max connection count 2 for 
  (smtp:10.16.245.217) at Jun  4 08:42:32
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max cache size 1 at Jun  4 08:42:27
Jun  4 08:46:07 zcs723 zmmailboxdmgr[2706]: status requested

In the /opt/zimbra/log/mailbox.log :

[root@zcs723 log]# egrep -C2 'ajcody|10.16.245.217' mailbox.log | grep -F 'Jun  4 08:4'

2013-06-04 08:43:00,343 INFO  [ImapServer-1] [] imap - [10.16.245.217] connected
2013-06-04 08:43:01,999 INFO  [ImapServer-1] [name=ajcody@zcs723.EXAMPLE.com;ip=10.16.245.217;
  ua=Mac OS X Mail/6.2 (1499);] imap - user ajcody@zcs723.EXAMPLE.com authenticated, mechanism=PLAIN [TLS]
2013-06-04 08:43:02,640 INFO  [ImapServer-2] [] imap - [10.16.245.217] connected
2013-06-04 08:43:04,031 INFO  [ImapServer-2] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  imap - user ajcody@zcs723.EXAMPLE.com authenticated, mechanism=PLAIN [TLS]
2013-06-04 08:43:04,721 WARN  [ImapServer-2] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  ConfigurationFactory - No configuration found. Configuring ehcache from ehcache-failsafe.xml  
  found in the classpath: 
  jar:file:/opt/zimbra/jetty-6.1.22.z6/webapps/service/WEB-INF/lib/ehcache-core-2.5.1.jar!/ehcache-failsafe.xml
2013-06-04 08:43:05,010 WARN  [ImapServer-2] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  ConfigurationFactory - No configuration found. Configuring ehcache from ehcache-failsafe.xml  
  found in the classpath: 
  jar:file:/opt/zimbra/jetty-6.1.22.z6/webapps/service/WEB-INF/lib/ehcache-core-2.5.1.jar!/ehcache-failsafe.xml
2013-06-04 08:43:05,420 INFO  [ImapServer-2] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  imap - selected folder INBOX
2013-06-04 08:43:05,922 INFO  [ImapServer-3] [] imap - [10.16.245.217] connected
2013-06-04 08:43:07,390 INFO  [ImapServer-3] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  imap - user ajcody@zcs723.EXAMPLE.com authenticated, mechanism=PLAIN [TLS]
2013-06-04 08:43:08,220 INFO  [ImapServer-4] [] imap - [10.16.245.217] connected
2013-06-04 08:43:09,437 INFO  [ImapServer-4] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  imap - user ajcody@zcs723.EXAMPLE.com authenticated, mechanism=PLAIN [TLS]
2013-06-04 08:43:10,395 INFO  [ImapServer-1] [] imap - dropping connection for user 
  ajcody@zcs723.EXAMPLE.com (server-initiated)
2013-06-04 08:43:10,395 INFO  [ImapServer-1] [] ProtocolHandler - Handler exiting normally
2013-06-04 08:43:10,447 INFO  [ImapServer-5] [] imap - [10.16.245.217] connected
2013-06-04 08:43:11,645 INFO  [ImapServer-5] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] 
  imap - user ajcody@zcs723.EXAMPLE.com authenticated, mechanism=PLAIN [TLS]
2013-06-04 08:43:12,521 INFO  [ImapServer-3] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Contacts
2013-06-04 08:43:12,685 INFO  [ImapServer-4] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Emailed Contacts
2013-06-04 08:43:13,813 INFO  [ImapServer-3] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Junk
2013-06-04 08:43:13,971 INFO  [ImapServer-5] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Sent
2013-06-04 08:43:15,614 INFO  [ImapServer-3] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Trash
2013-06-04 08:43:16,694 INFO  [ImapServer-4] [name=ajcody@zcs723.EXAMPLE.com;mid=15;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Chats
2013-06-04 08:43:17,211 INFO  [ImapServer-3] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Emailed Contacts
2013-06-04 08:43:17,344 INFO  [ImapServer-2] [name=ajcody@zcs723.EXAMPLE.com;mid=15;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Drafts
2013-06-04 08:43:17,358 INFO  [ImapServer-3] [name=ajcody@zcs723.EXAMPLE.com;mid=15;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder INBOX
2013-06-04 08:43:17,840 INFO  [ImapServer-4] [name=ajcody@zcs723.EXAMPLE.com;
  ip=10.16.245.217;ua=Mac OS X Mail/6.2 (1499);] imap - selected folder Emailed Contacts
2013-06-04 08:44:00,813 INFO  [MailboxPurge] [name=ajcody@zcs723.EXAMPLE.com;mid=15;] 
  purge - Purging messages.
2013-06-04 08:44:41,428 INFO  [btpool0-28://zcs723.EXAMPLE.com/service/soap/NoOpRequest] 
  [name=ajcody2@zcs723.EXAMPLE.com;mid=16;ip=10.16.245.217;ua=ZimbraWebClient - [unknown] (Win)/0.0;] 
  soap - NoOpRequest elapsed=0
2013-06-04 08:45:00,818 INFO  [MailboxPurge] [name=ajcody2@zcs723.EXAMPLE.com;mid=16;] 
  purge - Purging messages.

The /var/log/messages and /var/log/maillog had the same events:

[root@zcs723 log]# egrep -C2 'ajcody|10.16.245.217' /var/log/messages | grep -F 'Jun  4 08:42'
Jun  4 08:42:07 zcs723 zmmailboxdmgr[1389]: status requested
Jun  4 08:42:07 zcs723 zmmailboxdmgr[1389]: status OK
Jun  4 08:42:27 zcs723 postfix/smtpd[1487]: connect from unknown[10.16.245.217]
Jun  4 08:42:28 zcs723 postfix/smtpd[1487]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: SSL_accept error from unknown[10.16.245.217]: -1
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: lost connection after STARTTLS from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: disconnect from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: connect from unknown[10.16.245.217]
Jun  4 08:42:31 zcs723 postfix/smtpd[1487]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:31 zcs723 postfix/smtpd[1487]: Anonymous TLS connection established 
  from unknown[10.16.245.217]: TLSv1 with cipher AES128-SHA (128/128 bits)
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: connect from unknown[10.16.245.217]
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: Anonymous TLS connection established 
  from unknown[10.16.245.217]: TLSv1 with cipher AES128-SHA (128/128 bits)
Jun  4 08:42:34 zcs723 postfix/smtpd[1497]: disconnect from unknown[10.16.245.217]
Jun  4 08:42:34 zcs723 postfix/smtpd[1487]: lost connection after EHLO from unknown[10.16.245.217]
Jun  4 08:42:34 zcs723 postfix/smtpd[1487]: disconnect from unknown[10.16.245.217]
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max connection rate 3/60s 
  for (smtp:10.16.245.217) at Jun  4 08:42:32
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max connection count 2 
  for (smtp:10.16.245.217) at Jun  4 08:42:32
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max cache size 1 at Jun  4 08:42:27

[root@zcs723 log]# egrep -C2 'ajcody|10.16.245.217' /var/log/maillog | grep -F 'Jun  4 08:42'
Jun  4 08:42:07 zcs723 zmmailboxdmgr[1389]: status requested
Jun  4 08:42:07 zcs723 zmmailboxdmgr[1389]: status OK
Jun  4 08:42:27 zcs723 postfix/smtpd[1487]: connect from unknown[10.16.245.217]
Jun  4 08:42:28 zcs723 postfix/smtpd[1487]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: SSL_accept error from unknown[10.16.245.217]: -1
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: lost connection after STARTTLS from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: disconnect from unknown[10.16.245.217]
Jun  4 08:42:30 zcs723 postfix/smtpd[1487]: connect from unknown[10.16.245.217]
Jun  4 08:42:31 zcs723 postfix/smtpd[1487]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:31 zcs723 postfix/smtpd[1487]: Anonymous TLS connection established 
  from unknown[10.16.245.217]: TLSv1 with cipher AES128-SHA (128/128 bits)
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: connect from unknown[10.16.245.217]
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: setting up TLS connection from unknown[10.16.245.217]
Jun  4 08:42:32 zcs723 postfix/smtpd[1497]: Anonymous TLS connection established 
  from unknown[10.16.245.217]: TLSv1 with cipher AES128-SHA (128/128 bits)
Jun  4 08:42:34 zcs723 postfix/smtpd[1497]: disconnect from unknown[10.16.245.217]
Jun  4 08:42:34 zcs723 postfix/smtpd[1487]: lost connection after EHLO from unknown[10.16.245.217]
Jun  4 08:42:34 zcs723 postfix/smtpd[1487]: disconnect from unknown[10.16.245.217]
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max connection rate 3/60s 
  for (smtp:10.16.245.217) at Jun  4 08:42:32
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max connection count 2 
  for (smtp:10.16.245.217) at Jun  4 08:42:32
Jun  4 08:45:54 zcs723 postfix/anvil[1489]: statistics: max cache size 1 at Jun  4 08:42:27

IMAP Test Via Telnet And Logging Events Of It - Proxy Included


### TELNET FROM CLIENT ###
# telnet zcs806.DOMAIN.com 143 
Trying 192.168.27.36...
Connected to zcs806.DOMAIN.com.
Escape character is '^]'.
* OK IMAP4 ready
01 LOGIN proxylogtest@zcs806.DOMAIN.com [REPLACE WITH ACCT PASSWORD]
01 OK [CAPABILITY IMAP4rev1 ACL BINARY CATENATE CHILDREN CONDSTORE ENABLE ESEARCH ESORT 
I18NLEVEL=1 ID IDLE LIST-EXTENDED LIST-STATUS LITERAL+ LOGIN-REFERRALS MULTIAPPEND 
NAMESPACE QRESYNC QUOTA RIGHTS=ektx SASL-IR SEARCHRES SORT THREAD=ORDEREDSUBJECT 
UIDPLUS UNSELECT WITHIN XLIST] LOGIN completed
01 logout

### LOGS ON ZCS SERVER ###

[zimbra@zcs806 log]$ egrep "192\.168\.27\.37|proxylogtest" *

nginx.log:2014/02/28 09:32:16 [info] 25611#0: *2595 client 192.168.27.37 connected to 0.0.0.0:143
nginx.log:2014/02/28 09:32:38 [info] 25611#0: *2595 client logged in, client: 192.168.27.37, 
       server: 0.0.0.0:143, login: "proxylogtest@zcs806.DOMAIN.com", upstream: 192.168.27.36:7993 
       (192.168.27.37:45080-192.168.27.36:143) <=> (192.168.27.36:53326-192.168.27.36:7993)

audit.log:2014-02-28 09:32:35,532 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
       via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] security - cmd=Auth; 
       account=proxylogtest@zcs806.DOMAIN.com; protocol=imap;

mailbox.log:2014-02-28 09:32:35,527 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;   
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] imap - ID elapsed=8
mailbox.log:2014-02-28 09:32:35,743 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailbox - Creating database 
      mboxgroup50
mailbox.log:2014-02-28 09:32:37,986 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailbox - 
      Creating mailbox with id 50 and group id 50 for proxylogtest@zcs806.DOMAIN.com.
mailbox.log:2014-02-28 09:32:37,986 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] cache - initializing folder 
      and tag caches for mailbox 50
mailbox.log:2014-02-28 09:32:37,987 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder ROOT: 
      id=11, parentId=11.
mailbox.log:2014-02-28 09:32:38,010 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Tags: 
      id=8, parentId=11.
mailbox.log:2014-02-28 09:32:38,011 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder 
      Conversations: id=9, parentId=11.
mailbox.log:2014-02-28 09:32:38,011 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder 
      Comments: id=17, parentId=11.
mailbox.log:2014-02-28 09:32:38,012 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder 
      USER_ROOT: id=1, parentId=11.
mailbox.log:2014-02-28 09:32:38,012 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Inbox: 
      id=2, parentId=1.
mailbox.log:2014-02-28 09:32:38,013 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Trash: 
      id=3, parentId=1.
mailbox.log:2014-02-28 09:32:38,013 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Junk: 
      id=4, parentId=1.
mailbox.log:2014-02-28 09:32:38,014 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Sent: 
      id=5, parentId=1.
mailbox.log:2014-02-28 09:32:38,014 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Drafts: 
      id=6, parentId=1.
mailbox.log:2014-02-28 09:32:38,015 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Contacts: 
      id=7, parentId=1.
mailbox.log:2014-02-28 09:32:38,023 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Calendar: 
      id=10, parentId=1.
mailbox.log:2014-02-28 09:32:38,023 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder Tasks: 
      id=15, parentId=1.
mailbox.log:2014-02-28 09:32:38,024 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder 
      Emailed Contacts: id=13, parentId=1.
mailbox.log:2014-02-28 09:32:38,024 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder 
      Chats: id=14, parentId=1.
mailbox.log:2014-02-28 09:32:38,025 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mailop - adding folder 
      Briefcase: id=16, parentId=1.
mailbox.log:2014-02-28 09:32:38,038 INFO  [Index-8] [name=proxylogtest@zcs806.DOMAIN.com;mid=50;] 
      index - Batch complete processed=0,failed=0,elapsed=1 (0.00 items/sec)
mailbox.log:2014-02-28 09:32:38,071 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] index - OpenLuceneIndex 
      impl=NIOFSDirectory,dir=/opt/zimbra/index/0/50/index/0
mailbox.log:2014-02-28 09:32:38,071 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
      via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] mbxmgr - Mailbox 50 
      account 0028aab0-3d17-4c51-aad8-da7500247079 CREATED
mailbox.log:2014-02-28 09:32:38,079 INFO  [ImapSSLServer-13] [name=proxylogtest@zcs806.DOMAIN.com;
      ip=192.168.27.36;oip=192.168.27.37;via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
      imap - user proxylogtest@zcs806.DOMAIN.com authenticated, mechanism=LOGIN [TLS]
mailbox.log:2014-02-28 09:32:38,079 INFO  [ImapSSLServer-13] [name=proxylogtest@zcs806.DOMAIN.com;
      ip=192.168.27.36;oip=192.168.27.37;via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
      imap - LOGIN elapsed=2550
mailbox.log:2014-02-28 09:32:46,258 WARN  [ImapSSLServer-16] [name=proxylogtest@zcs806.DOMAIN.com;
      ip=192.168.27.36;oip=192.168.27.37;via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
      imap - BAD parse error: command not implemented
mailbox.log:2014-02-28 09:32:46,258 INFO  [ImapSSLServer-16] [name=proxylogtest@zcs806.DOMAIN.com;
      ip=192.168.27.36;oip=192.168.27.37;via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
      imap - EXIT elapsed=1
mailbox.log:2014-02-28 09:32:48,648 WARN  [ImapSSLServer-13] [name=proxylogtest@zcs806.DOMAIN.com;
      ip=192.168.27.36;oip=192.168.27.37;via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
      imap - BAD parse error: command not implemented
mailbox.log:2014-02-28 09:32:48,648 INFO  [ImapSSLServer-13] [name=proxylogtest@zcs806.DOMAIN.com;
      ip=192.168.27.36;oip=192.168.27.37;via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
      imap - QUIT elapsed=1

IMAP Login Via Openssl - LOGIN TLS - Proxy Included

You would run from the CLI:

 openssl s_client -crlf -connect zcs806.DOMAIN.com:993

Once it shows "* OK IMAP4 ready" you'll be able to give the login command:

tag login proxylogtest@zcs806.DOMAIN.com PASSWORD

Another good example of this is at Access IMAP server from the command line using OpenSSL

The log events for this are:

$ egrep "192\.168\.27\.37|proxylogtest" * | grep "28 10"

audit.log:2014-02-28 10:37:51,207 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
    via=192.168.27.36(nginx/1.2.0-zimbra); ua=Zimbra/8.0.6_GA_5922;] security - cmd=Auth; 
    account=proxylogtest@zcs806.DOMAIN.com; protocol=imap;

mailbox.log:2014-02-28 10:37:51,204 INFO  [ImapSSLServer-13] [ip=192.168.27.36;oip=192.168.27.37;
    via=192.168.27.36(nginx/1.2.0-zimbra); ua=Zimbra/8.0.6_GA_5922;] imap - ID elapsed=1
mailbox.log:2014-02-28 10:37:51,207 INFO  [ImapSSLServer-13] [name=proxylogtest@zcs806.DOMAIN.com;
    ip=192.168.27.36;oip=192.168.27.37; via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
    imap - user proxylogtest@zcs806.DOMAIN.com authenticated, mechanism=LOGIN [TLS]
mailbox.log:2014-02-28 10:37:51,207 INFO  [ImapSSLServer-13] [name=proxylogtest@zcs806.DOMAIN.com;
    ip=192.168.27.36;oip=192.168.27.37; via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
    imap - LOGIN elapsed=2
mailbox.log:2014-02-28 10:38:10,132 INFO  [ImapSSLServer-13] [name=proxylogtest@zcs806.DOMAIN.com;
    ip=192.168.27.36;oip=192.168.27.37; via=192.168.27.36(nginx/1.2.0-zimbra);ua=Zimbra/8.0.6_GA_5922;] 
    imap - LIST elapsed=12

nginx.log:2014/02/28 10:32:01 [info] 25609#0: *2602 client 192.168.27.37 connected to 0.0.0.0:993
nginx.log:2014/02/28 10:37:07 [info] 25609#0: *2603 client 192.168.27.37 connected to 0.0.0.0:993
nginx.log:2014/02/28 10:37:51 [info] 25609#0: *2603 client logged in, client: 192.168.27.37, server: 0.0.0.0:993, 
    login: "proxylogtest@zcs806.DOMAIN.com", upstream: 192.168.27.36:7993 
    (192.168.27.37:41009-192.168.27.36:993) <=> (192.168.27.36:53613-192.168.27.36:7993)

Additional Content

  • No related content.
Verified Against: Zimbra Collaboration 8.6, 8.5, 8.0 Date Created: 04/16/2015
Article ID: https://wiki.zimbra.com/index.php?title=Understanding_And_Troubleshooting_Authentication_Log_Events Date Modified: 2015-04-25



Try Zimbra

Try Zimbra Collaboration with a 60-day free trial.
Get it now »

Want to get involved?

You can contribute in the Community, Wiki, Code, or development of Zimlets.
Find out more. »

Looking for a Video?

Visit our YouTube channel to get the latest webinars, technology news, product overviews, and so much more.
Go to the YouTube channel »


Wiki/KB reviewed by SME1 SME2 Copyeditor Last edit by Jorge de la Cruz
Jump to: navigation, search