Zimbra offers Open Source email server software and shared calendar for Linux and the Mac
Go Back   Zimbra :: Forums > Zimbra Collaboration Suite > Administrators

Welcome to the Zimbra :: Forums!
Welcome, if you would like to post a comment please register. We also encourage you to explore all things Zimbra with our team and members of the community.

Reply
 
LinkBack Thread Tools Search this Thread Display Modes
  #1 (permalink)  
Old 12-03-2008, 05:46 AM
Senior Member
 
Posts: 55
Default Web sessions logged out all of a sudden

Hi there,

first of all congrats for this awesome piece of software. We are very pleased.

Anyways, just today at ~12.40 we had all web sessions logged out, admin included.

Here's what I've just found in mailbox.log:

Code:
[...]
2008-12-03 12:39:14,172 WARN  [btpool0-1731] [] SoapEngine - unable to construct SOAP context
com.zimbra.common.service.ServiceException: auth credentials have expired
ExceptionId:btpool0-1731:1228304354172:85d7468e46da65b8
Code:service.AUTH_EXPIRED
        at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
        at com.zimbra.soap.ZimbraSoapContext.<init>(ZimbraSoapContext.java:191)
        at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:190)
        at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:160)
        at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:269)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:189)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1093)
        at org.mortbay.servlet.UserAgentFilter.doFilter(UserAgentFilter.java:81)
        at org.mortbay.servlet.GzipFilter.doFilter(GzipFilter.java:132)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:716)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:406)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:211)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
        at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:350)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
        at org.mortbay.jetty.Server.handle(Server.java:313)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:506)
        at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:844)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:644)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:211)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:381)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:396)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)

[...]

2008-12-03 12:42:04,468 WARN  [btpool0-1732] [] SoapEngine - unable to construct SOAP context
com.zimbra.common.service.ServiceException: auth credentials have expired
ExceptionId:btpool0-1732:1228304524468:85d7468e46da65b8
Code:service.AUTH_EXPIRED
        at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
        at com.zimbra.soap.ZimbraSoapContext.<init>(ZimbraSoapContext.java:191)
        at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:190)
        at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:160)
        at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:269)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:189)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1093)
        at org.mortbay.servlet.UserAgentFilter.doFilter(UserAgentFilter.java:81)
        at org.mortbay.servlet.GzipFilter.doFilter(GzipFilter.java:132)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:716)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:406)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:211)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
        at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:350)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
        at org.mortbay.jetty.Server.handle(Server.java:313)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:506)
        at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:844)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:644)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:211)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:381)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:396)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)
[...]

Notice that we've never faced a situation like this one before. Nothing serious, it just made users reauth again and that's it, but still it's something scary, you know... At least as long as I don't understand why it happened in the first place...!

I thank you all in advance.

Marcello
Reply With Quote
  #2 (permalink)  
Old 12-03-2008, 10:14 PM
Trained Alumni
 
Posts: 108
Default

hmm that's odd. Does the mailbox.log file, in the entire Java Exception, say anything like "caused by ..." ?

Any chance ntpd/ntpclient would have set the clock forward ?
Reply With Quote
  #3 (permalink)  
Old 12-04-2008, 06:41 AM
Senior Member
 
Posts: 55
Default

Txs buddy, fast reply!

Nope, both suggested causes don't apply here:

- I checked NTP, I see no evidence of it messing around with system time. Maybe its reference NTP servers did this? I doubt it thou...
- Java doesn't say anything else... :-(

In the mean time, thanks again.
Reply With Quote
  #4 (permalink)  
Old 12-04-2008, 06:47 AM
Senior Member
 
Posts: 55
Default

Errr....

Paying some more attention, looks like it wasn't the first time...

Code:
#cd /opt/zimbra/log/ ; fgrep -r AUTH_EXPIRED *
mailbox.log:Code:service.AUTH_EXPIRED
mailbox.log:    at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log:Code:service.AUTH_EXPIRED
mailbox.log:    at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-11-26:Code:service.AUTH_EXPIRED
mailbox.log.2008-11-26: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-11-26:Code:service.AUTH_EXPIRED
mailbox.log.2008-11-26: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-11-28:Code:service.AUTH_EXPIRED
mailbox.log.2008-11-28: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-12-03:Code:service.AUTH_EXPIRED
mailbox.log.2008-12-03: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-12-03:Code:service.AUTH_EXPIRED
mailbox.log.2008-12-03: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
Reply With Quote
  #5 (permalink)  
Old 12-04-2008, 12:14 PM
Trained Alumni
 
Posts: 108
Default

Quote:
Originally Posted by caio80 View Post
Errr....

Paying some more attention, looks like it wasn't the first time...

Code:
#cd /opt/zimbra/log/ ; fgrep -r AUTH_EXPIRED *
mailbox.log:Code:service.AUTH_EXPIRED
mailbox.log:    at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log:Code:service.AUTH_EXPIRED
mailbox.log:    at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-11-26:Code:service.AUTH_EXPIRED
mailbox.log.2008-11-26: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-11-26:Code:service.AUTH_EXPIRED
mailbox.log.2008-11-26: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-11-28:Code:service.AUTH_EXPIRED
mailbox.log.2008-11-28: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-12-03:Code:service.AUTH_EXPIRED
mailbox.log.2008-12-03: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)
mailbox.log.2008-12-03:Code:service.AUTH_EXPIRED
mailbox.log.2008-12-03: at com.zimbra.common.service.ServiceException.AUTH_EXPIRED(ServiceException.java:287)

Did the problem occur on the same days that the AUTH_EXPIRED value is in those files ?
Reply With Quote
  #6 (permalink)  
Old 12-05-2008, 05:16 AM
Senior Member
 
Posts: 55
Default

Yes and no...

I mean, even today it happened, at 12:41. People noticed it, being forced to reauth, and reported it to me. I then checked my webclient, but in my case I didn't need to reauth again (linux client, firefox 3.0.4).

At the same time according to the logs there has been another AUTH_EXPIRED at 11.20 today (1h20m before), but this time nobody had any problem client-side!

Whatta... :-o
Reply With Quote
  #7 (permalink)  
Old 12-05-2008, 07:08 AM
Senior Member
 
Posts: 55
Default

UPDATE:

This time it happened again! But on a imap-client. It just said the "server wasn't reachable" or something like that.
By checking logs, there's another AUTH_EXPIRED just 10 minutes ago, but actually AFTER the user called me in to tell me his Thunderbird complained about not being able to communicate with the server... :-(


And now I start finding many of the following Java exceptions in the error log.

Code:
[...]
2008-12-05 11:51:16,570 INFO  [ImapServer-7060] [] ProtocolHandler - Exception occurred while handling connection
java.net.SocketException: Socket closed
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:235)
        at com.zimbra.cs.tcpserver.TcpServerInputStream.readLine(TcpServerInputStream.java:73)
        at com.zimbra.cs.imap.TcpImapRequest.continuation(TcpImapRequest.java:52)
        at com.zimbra.cs.imap.TcpImapHandler.processCommand(TcpImapHandler.java:106)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:160)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:128)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)
2008-12-05 15:16:02,092 INFO  [ImapServer-7444] [] ProtocolHandler - Handler exiting normally
[...]
Whatta.... again!

Any idea folks?

I thank you all in advance
Reply With Quote
  #8 (permalink)  
Old 12-05-2008, 09:16 AM
Moderator
 
Posts: 1,147
Default

It looks like (at least some of these entries) are happening at ~12:40...is there a cron task that is running that might be causing this?
Reply With Quote
  #9 (permalink)  
Old 12-09-2008, 12:21 AM
Senior Member
 
Posts: 55
Default

Quote:
It looks like (at least some of these entries) are happening at ~12:40...is there a cron task that is running that might be causing this?
Nope, already checked, but nothing's scheduled for ~12.40. And anyways time differs substantially (~2 mins, computer-wise though). Thanks anyways for the hint, ArcaneMagus.
Reply With Quote
  #10 (permalink)  
Old 12-09-2008, 12:22 AM
Senior Member
 
Posts: 55
Default

UPDATE #2:

As soon as I sat down this tuesday morning, back from this past long week-end, I checked logs to see how it behaved: No AUTH_EXPIRED in 3 full days. Notice that nobody obviouosly worked in the meantime!

Looks like "no use" == "no problem"...

Last edited by caio80; 12-10-2008 at 06:39 AM..
Reply With Quote
Reply


Thread Tools Search this Thread
Search this Thread:

Advanced Search
Display Modes


Similar Threads

Why Join?

Registering let's you ask questions, makes it easier to search, displays any files attached to posts, and notifies you about replies.

blog.zimbra.com




 

SEO by vBSEO ©2011, Crawlability, Inc.