[SOGo] Password change behavior

[Laz C. Peterson]

Can someone please fill me in on the expected behavior of SOGo after the user changes their password through preferences?

My users, who can change their passwords just fine through the preferences, get stuck in SOGo after changing the password. It appears as if they are still logged in, but if they go to write a new message or click on a different feature (such as Calendar), they are presented with a login box. (At this point, they can log in fine using their new password.)

I want to confirm that this is by design, or if there is something I need to look into. It seems that either the user should not have to relog in at all, or that the user should immediately be logged off and presented with a new login screen.

Thanks for any help.
~Laz--
users-***@public.gmane.org
https://inverse.ca/sogo/lists

[Jean Raby]

Post by Laz C. Peterson
Can someone please fill me in on the expected behavior of SOGo after the user changes their password through preferences?
My users, who can change their passwords just fine through the preferences, get stuck in SOGo after changing the password. It appears as if they are still logged in, but if they go to write a new message or click on a different feature (such as Calendar), they are presented with a login box. (At this point, they can log in fine using their new password.)
I want to confirm that this is by design, or if there is something I need to look into. It seems that either the user should not have to relog in at all, or that the user should immediately be logged off and presented with a new login screen.

Can you explain or post your sogo configuration?
Anything relevant in the logs?

I just tested this with sogo using openldap as its auth backend and it works as
designed. That is: when I change my password, I can still use sogo without
having to log back in.

Post by Laz C. Peterson
Thanks for any help.
~Laz--

[Laz C. Peterson]

Jean,

So I went to another computer of mine and tried both FireFox and Safari (sorry, no Windows systems here!) and neither worked properly. On my workstation, FireFox does not work, and in further testing, I noticed that Safari did not actually work every time. So I tried a little troubleshooting ...

I changed my password and stayed in the “Preferences” screen for a little while before clicking out. If I stay for a little while without clicking, it seems to work! If I close out almost immediately after and try doing other things, I get an error message something like "object not found: lpeterson-pvS6QR15nlVWVPTZF4YnfwC/***@public.gmane.org => Mail => 0 => compose”.

I do have “SOGoCacheCleanupInterval” set to 10, if that makes any difference.

Attached is the SOGo debug log when it does not work and the SOGo debug log when it does. I honestly don’t know the difference of what we’re looking at there. Maybe I can try and get some better-looking logs for you, just let me know how.

Also, the latency and connection between all of the servers is great (<0.3ms average) …

Thanks again Jean.
~Laz

[Jean Raby]

I do have “SOGoCacheCleanupInterval” set to 10, if that makes any difference.

Why is the cleanup interval set so low?

It should work anyway, but I'm curious. Also, for the record, I was testing with
chrome. (with the default cache cleanup interval: 300)

[Laz C. Peterson]

Yikes.

Then if it shouldn’t matter, I’m sure there’s something else going on here.

Any suggestions for how I can investigate? If I leave it sitting long enough before I click something, maybe 10-15 seconds, then it seems to work as designed.

If I click slightly too fast, here are a couple things that happen (if using the same browser/computer) …
1- Any page or link I click to shows up in its frame or window as the login screen.
2- Next time I log in, after putting in correct username and password, SOGo “logs in” but does not actually get past the login page. I have copied and pasted passwords to make sure that it is exact. Same result.

I have tested this on 3 computers with similar results (all Mac, diff versions), and for right now on my workstation, I’m unable to change the password and wait any period of time at all for it to work correctly. On my wife’s laptop, I can still do it, but I have to wait at least 10-15 seconds.

Please give me a step-by-step on how I can get some valuable information. Hopefully I can get you back some good information that might help the future releases. I really don’t think anything on my side is out of the ordinary. If so, please help me prove it. =]

I appreciate all of your time and efforts. Thanks again.
~Laz

Post by Jean Raby

I do have “SOGoCacheCleanupInterval” set to 10, if that makes any difference.

Why is the cleanup interval set so low?
It should work anyway, but I'm curious. Also, for the record, I was testing with chrome. (with the default cache cleanup interval: 300)
--
https://inverse.ca/sogo/lists

[Jean Raby]

Post by Laz C. Peterson
Yikes.
Then if it shouldn’t matter, I’m sure there’s something else going on here.

I'll test it. But why are you running with a 10 seconds cache expiration? that's
really low.

[Jean Raby]

Post by Jean Raby

Post by Laz C. Peterson
Yikes.
Then if it shouldn’t matter, I’m sure there’s something else going on here.

I'll test it. But why are you running with a 10 seconds cache expiration? that's
really low.

I think you're running with passwordpolicy enable in sogo, but the
passowrdpolicy overlay is not enabled in openldap.

Just disable password policy in your sogo user source and it will work properly.

Also, you didn't provide your config file, it would have saved us time and
trouble if you had...

(finally, unless you have a good reason to set the cache cleanup interval so
low, you're probably better off keeping it at its default value)

[Laz C. Peterson]

Jean,

My apologies for no config file (now attached).  I do have ppolicy enabled in the LDAP server, though I am also running another module called "smbkrb5pwd" which synchronizes/updates the user's Kerberos password as well.  I am not sure if this has any effect, though it may.  I can confirm that user changing password through SOGo preferences immediately updates both Kerberos and LDAP passwords successfully, and user can authenticate through Kerberos or LDAP with no issues using their new password with other services.

As you can see, I have now disabled the manual setting of SOGoCacheCleanupInterval.  I only had that set due to another post I had read, not because I felt I needed it.  (Bad idea on my part.)

The most interesting thing I have found is that when the "issue" happens, I am not able to log in using any browser for a period of time.  I feel that changing SOGoCacheCleanupInterval to default affects this even more, though I really have no idea.  SOGo authenticates successfully, but never makes it past the login screen.  The URL that shows after attempted (successful?) login is https://sogo.myemaildomain.com/SOGo/lpeterson ... Not the usual https://sogo.myemaildomain.com/SOGo/so/***@myemaildomain.com/Mail/view.  And if I type a bad password (for example, the old password), it does respond with incorrect password

I am thinking there must be the old password cached somewhere between SOGo, LDAP, KDC, or IMAP, but the updated password works quickly for LDAP, KDC, and IMAP services.  Relevant services along with SOGo 2.1.1 (Ubuntu 12.04.3) are OpenLDAP v2.4.28 (Ubuntu 12.04.3) and Dovecot v2.1.7 (Ubuntu 13.04).

Today is a really bad day for me, but as soon as I get a chance, I am going to look into the smbkrb5pwd module that is running alongside ppolicy.  I will gladly take any other suggestions, too.

I do appreciate your help very much.  If there is anything I can do to help provide more information, please let me know how I can do that.  Thanks again Jean.  This is a wonderful piece of software and I am very grateful for your efforts.
~Laz

Post by Jean Raby

Post by Laz C. Peterson
Yikes.
Then if it shouldn’t matter, I’m sure there’s something else going on here.

I'll test it. But why are you running with a 10 seconds cache expiration? that's
really low.

I think you're running with passwordpolicy enable in sogo, but the
passowrdpolicy overlay is not enabled in openldap.

Just disable password policy in your sogo user source and it will work properly.

Also, you didn't provide your config file, it would have saved us time and
trouble if you had...

(finally, unless you have a good reason to set the cache cleanup interval so
low, you're probably better off keeping it at its default value)
--
users-***@public.gmane.org
https://inverse.ca/sogo/lists
 

[Laz C. Peterson]

Also, maybe this will help.  I get messages like this, when trying to open up other windows ...

"object not found: lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org => Mail => 0 => folderINBOX => 1 => popupview"
"object not found: lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org => preferences"
"object not found: lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org => logoff"

Sometimes it works flawlessly without any logging off or on.  Most of the time the problem is taken care of within 1 minute.  Rarely, but sometimes, the issue takes over 3 minutes until the user can log back in again.

No cookies or cache on the user's side are impacting this issue.  Authentication and mail servers seem to work fine without any issue.  I can only think there might be an issue within the SOGo database or cache?

Thank you.
~Laz

Post by Jean Raby

Post by Laz C. Peterson
Yikes.
Then if it shouldn’t matter, I’m sure there’s something else going on here.

I'll test it. But why are you running with a 10 seconds cache expiration? that's
really low.

I think you're running with passwordpolicy enable in sogo, but the
passowrdpolicy overlay is not enabled in openldap.

Just disable password policy in your sogo user source and it will work properly.

Also, you didn't provide your config file, it would have saved us time and
trouble if you had...

(finally, unless you have a good reason to set the cache cleanup interval so
low, you're probably better off keeping it at its default value)
--
users-***@public.gmane.org
https://inverse.ca/sogo/lists
 --
users-***@public.gmane.org
https://inverse.ca/sogo/lists

[Laz C. Peterson]

Jean~

I cannot seem to figure this out for my life ... (Let's hope it doesn't kill me! Ha ha ha.)

I know you are a busy man, but if you could point me in the right direction I would greatly appreciate it.  Let me break down the summary of the issue.

-- No other services are running on the server except for SOGo.  Nothing aside from my config has been modified.
-- User changes password, and password is immediately updated in the LDAP database as well as the Kerberos database.  User can authenticate immediately to any Kerberos services as well as LDAP services using the new password.
-- After closing "Preferences" window, about 70-80% of the time, clicking anywhere brings up the login page.
-- If the login page does not show when clicking on any other SOGo link, all is well.
-- If the login page does show, most of the time the user will still be unable to log on, even if the user goes to another computer and tries a new session.  The only way I can describe the behavior here is that if the "usual" URL after a successful login is https://sogo.paravis.net/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/view, the URL after an unsuccessful login is simply https://sogo.paravis.net/SOGo/so/lpeterson.
-- User must wait an undefined period of time, after which everything works again with the new password.

I am going to try rebuilding a new server for testing purposes, but I can confirm that all LDAP and Kerberos authentication is working great.  The password changes perfectly through SOGo.  It seems though that SOGo has something cached in its memory that is not being renewed when the password changes.  Or maybe it is receiving a response from the LDAP server that makes it confused.

Which debug information should I focus my efforts on?  Or how would you suggest troubleshooting?  I am truly baffled.  Thank you so much Jean.
~Laz

Post by Jean Raby

Post by Laz C. Peterson
Yikes.
Then if it shouldn’t matter, I’m sure there’s something else going on here.

I'll test it. But why are you running with a 10 seconds cache expiration? that's
really low.

I think you're running with passwordpolicy enable in sogo, but the
passowrdpolicy overlay is not enabled in openldap.

Just disable password policy in your sogo user source and it will work properly.

Also, you didn't provide your config file, it would have saved us time and
trouble if you had...

(finally, unless you have a good reason to set the cache cleanup interval so
low, you're probably better off keeping it at its default value)
--
users-***@public.gmane.org
https://inverse.ca/sogo/lists
 --
users-***@public.gmane.org
https://inverse.ca/sogo/lists

[Laz C. Peterson]

Here is the most detailed log that I can provide for you.  I truly hope this helps.  Thanks.

Nov 24 19:40:59 sogod [10859]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d2e7940[SOGoCache]> Cache cleanup interval set every 5.000000 seconds
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d2e7940[SOGoCache]> Using host(s) 'localhost' as server(s)
2013-11-24 19:40:59.667 sogod[10859] Note(SoObject): SoDebugKeyLookup is enabled!
2013-11-24 19:40:59.667 sogod[10859] Note(SoObject): SoDebugBaseURL is enabled!
2013-11-24 19:40:59.668 sogod[10859] Note(SoObject): relative base URLs are enabled.
2013-11-24 19:40:59.674 sogod[10859] ERROR(-[NGBundleManager bundleWithPath:]): could not create bundle for path: '/usr/share/GNUstep/Libraries/gnustep-base/Versions/1.22/Resources/SSL.bundle'
2013-11-24 19:40:59.681 sogod[10859] WOxElemBuilder: could not locate builders: WOxExtElemBuilder,WOxExtElemBuilder
2013-11-24 19:40:59.682 sogod[10859] WOCompoundElement: pool embedding is on.
2013-11-24 19:40:59.682 sogod[10859] WOCompoundElement: id logging is on.
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d6380b0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d623310[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:40:59.692 sogod[10859] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter '(objectClass=*)' for attrs 'subschemaSubentry'
2013-11-24 19:40:59.693 sogod[10859] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'cn=Subschema' filter '(objectClass=*)' for attrs 'objectclasses'
2013-11-24 19:40:59.700 sogod[10859] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(uid=lpeterson)' for attrs 'dn'
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d6380b0[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d6380b0[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:40:59 sogod [10859]: SOGoRootPage successful login from '10.0.2.102' for user 'lpeterson' - expire = -1  grace = -1
2013-11-24 19:40:59.709 sogod[10859] MySQL4 connection established 0x0x7f692d694210
2013-11-24 19:40:59.710 sogod[10859] MySQL4 channel 0x0x7f692d6477c0 opened (connection=0x0x7f692d694210,sogo_db)
2013-11-24 19:40:59.710 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: BEGIN;
2013-11-24 19:40:59.711 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210>   query has no results.
2013-11-24 19:40:59.712 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM  sogo_sessions_folder t1 WHERE t1.c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:40:59.713 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210>   query has results, entering fetch-mode.
2013-11-24 19:40:59.713 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: ROLLBACK;
2013-11-24 19:40:59.714 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210>   query has no results.
2013-11-24 19:40:59.714 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:40:59.716 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:40:59.716 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: INSERT INTO sogo_sessions_folder (c_value, c_lastseen, c_creationdate, c_id) VALUES ('0OZ4qikKJuVG9n4UolB4ajSKwNUUmMJhAyKgDat+zcDF3zF5YHj/PSKJnBEYWBtTLhi9i+h4CAIYaZn+4dd2iMHyTSw5nw5IczqF2tIltxuaGjg4HrVao+2OE3Q3hTrmXNiVDPnSfTZ4J5XsVnSx3RMDwICJX81sP5HQNBH1BO9ah2aRPCwBmlyhb+Pk/zG3nIZDRNDmwxJmrJ3UCPM7XA==', 1385350859, 1385350859, 'kE+e2W9TTt5DQKr34+MXNg==');
2013-11-24 19:40:59.717 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:40:59.718 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: COMMIT;
2013-11-24 19:40:59.718 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d6c7740[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:40:59.722 sogod[10859] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(|(uid=lpeterson)(mail=lpeterson))' for attrs '*'
Nov 24 19:40:59 sogod [10859]: [WARN] <0x0x7f692d7077e0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Nov 24 19:40:59 sogod [10859]: [WARN] <0x0x7f692d7077e0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Nov 24 19:40:59 sogod [10859]: [WARN] <0x0x7f692d7077e0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
2013-11-24 19:40:59.728 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: SELECT c_settings FROM sogo_user_profile WHERE c_uid = 'lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org';
2013-11-24 19:40:59.729 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210>   query has results, entering fetch-mode.
Nov 24 19:40:59 sogod [10859]: |SOGo| request took 0.066954 seconds to execute
2013-11-24 19:40:59.732 sogod[10859] Note: Using UTF-8 as URL encoding in NGExtensions.
10.0.2.102 - - [24/Nov/2013:19:40:59 GMT] "POST /SOGo/connect HTTP/1.1" 200 27/53 0.073 - - 3M
Nov 24 19:40:59 sogod [10859]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson'
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d596e00[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d596e00[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d596e00[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:40:59 sogod [10859]: |SOGo| request took 0.007301 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:40:59 GMT] "GET /SOGo/so/lpeterson HTTP/1.1" 302 0/0 0.010 - - 36K
Nov 24 19:40:59 sogod [10859]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson/view'
2013-11-24 19:40:59.919 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: SELECT c_defaults FROM sogo_user_profile WHERE c_uid = 'lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org';
2013-11-24 19:40:59.920 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has results, entering fetch-mode.
Nov 24 19:40:59 sogod [10859]: |SOGo|   constructed root-url: /SOGo/
Nov 24 19:40:59 sogod [10859]: |SOGo|   setting root-url in context: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: <0x2D65E730[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/lpeterson/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:40:59 sogod [10859]: |SOGo| request took 0.007516 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:40:59 GMT] "GET /SOGo/so/lpeterson/view HTTP/1.1" 302 0/0 0.010 - - 8K
Nov 24 19:40:59 sogod [10859]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail'
Nov 24 19:40:59 sogod [10859]: |SOGo| request took 0.002355 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:40:59 GMT] "GET /SOGo/so/***@mydomain.com/Mail HTTP/1.1" 302 0/0 0.004 - - 0
Nov 24 19:40:59 sogod [10859]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/view'
Nov 24 19:40:59 sogod [10859]: |SOGo|   constructed root-url: /SOGo/
Nov 24 19:40:59 sogod [10859]: |SOGo|   setting root-url in context: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: <0x2D662300[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:40:59 sogod [10859]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: <0x2D662300[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:40:59 sogod [10859]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: <0x2D662300[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:40:59 sogod [10859]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: <0x2D662300[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
2013-11-24 19:41:00.007 sogod[10859] WARNING: IMAP4 connection pooling is disabled!
2013-11-24 19:41:00.166 sogod[10859] Note(NGImap4Connection): using '/' as the IMAP4 folder separator.
Nov 24 19:41:00 sogod [10859]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: <0x2D662300[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:00 sogod [10859]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: <0x2D662300[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:00 sogod [10859]: <0x2D638F20[SOGoMailAccounts]:Mail> baseURL: name=Mail (container=SOGoUserFolder)
  container: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail
Nov 24 19:41:00 sogod [10859]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: <0x2D662300[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:00 sogod [10859]: |SOGo| request took 0.468720 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:00 GMT] "GET /SOGo/so/***@mydomain.com/Mail/view HTTP/1.1" 200 8168/0 0.472 32914 75% 3M
Nov 24 19:41:00 sogod [10859]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Calendar/alarmslist?browserTime=1385350860'
2013-11-24 19:41:00.870 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org' AND c_folder_type = 'Appointment';
2013-11-24 19:41:00.871 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210>   query has results, entering fetch-mode.
2013-11-24 19:41:00.874 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: SELECT c_folder_id, c_path, c_location, c_quick_location, c_acl_location, c_folder_type FROM sogo_folder_info WHERE c_path1 = 'Users' AND c_path2 = 'lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org' AND c_path3 = 'Calendar' AND c_path4 = 'personal';
2013-11-24 19:41:00.875 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has results, entering fetch-mode.
2013-11-24 19:41:00.876 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: SELECT b.c_name,a.c_nextalarm,a.c_iscycle FROM sogolpeterso0010c7593f5_quick a, sogolpeterso0010c7593f5 b WHERE (((c_nextalarm <= 1385523660) AND (c_nextalarm >= 1385350860)) OR ((c_nextalarm > 0) AND (c_enddate > 1385350860))) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL);
2013-11-24 19:41:00.881 sogod[10860] Note: Using UTF-8 as URL encoding in NGExtensions.
Nov 24 19:41:00 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/0/mailboxes'2013-11-24 19:41:00.882 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210>   query has results, entering fetch-mode.
Nov 24 19:41:00 sogod [10859]: |SOGo| request took 0.014768 seconds to execute
Nov 24 19:41:00 sogod [10860]: <0x0x7f692d2d0990[SOGoCache]> Cache cleanup interval set every 5.000000 seconds
Nov 24 19:41:00 sogod [10860]: <0x0x7f692d2d0990[SOGoCache]> Using host(s) 'localhost' as server(s)10.0.2.102 - - [24/Nov/2013:19:41:00 GMT] "POST /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Calendar/alarmslist?browserTime=1385350860 HTTP/1.1" 200 2/0 0.019 - - 0
2013-11-24 19:41:00.889 sogod[10860] Note(SoObject): SoDebugKeyLookup is enabled!
2013-11-24 19:41:00.889 sogod[10860] Note(SoObject): SoDebugBaseURL is enabled!
2013-11-24 19:41:00.889 sogod[10860] Note(SoObject): relative base URLs are enabled.
2013-11-24 19:41:00.893 sogod[10860] WARNING: IMAP4 connection pooling is disabled!
2013-11-24 19:41:01.044 sogod[10860] Note(NGImap4Connection): using '/' as the IMAP4 folder separator.
Nov 24 19:41:01 sogod [10860]: |SOGo| request took 0.323621 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:01 GMT] "POST /SOGo/so/***@mydomain.com/Mail/0/mailboxes HTTP/1.1" 200 402/0 0.329 - - 2M
Nov 24 19:41:01 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/0/folderINBOX/unseenCount'
Nov 24 19:41:01 sogod [10859]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/foldersState'
Nov 24 19:41:01 sogod [10859]: |SOGo| request took 0.007251 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:01 GMT] "POST /SOGo/so/***@mydomain.com/Mail/foldersState HTTP/1.1" 200 0/0 0.010 - - 0
Nov 24 19:41:01 sogod [10860]: |SOGo| request took 0.358742 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:01 GMT] "POST /SOGo/so/***@mydomain.com/Mail/0/folderINBOX/unseenCount HTTP/1.1" 200 13/0 0.368 - - 0
Nov 24 19:41:03 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/preferences'
2013-11-24 19:41:03.099 sogod[10860] ERROR(-[NGBundleManager bundleWithPath:]): could not create bundle for path: '/usr/share/GNUstep/Libraries/gnustep-base/Versions/1.22/Resources/SSL.bundle'
2013-11-24 19:41:03.115 sogod[10860] WOxElemBuilder: could not locate builders: WOxExtElemBuilder,WOxExtElemBuilder
2013-11-24 19:41:03.115 sogod[10860] WOCompoundElement: pool embedding is on.
2013-11-24 19:41:03.115 sogod[10860] WOCompoundElement: id logging is on.
Nov 24 19:41:03 sogod [10860]: |SOGo|   constructed root-url: /SOGo/
Nov 24 19:41:03 sogod [10860]: |SOGo|   setting root-url in context: /SOGo/so/
Nov 24 19:41:03 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:03 sogod [10860]: <0x2D5EF990[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/preferences
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:03 sogod [10860]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:03 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:03 sogod [10860]: <0x2D5EF990[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/preferences
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:03 sogod [10860]: |SOGo| request took 0.089552 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:03 GMT] "GET /SOGo/so/***@mydomain.com/preferences HTTP/1.1" 200 14645/0 0.095 65972 77% 4M
Nov 24 19:41:15 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/so/changePassword'
2013-11-24 19:41:15.879 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:41:15.880 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:41:15.881 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM  sogo_sessions_folder t1 WHERE t1.c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:41:15.882 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has results, entering fetch-mode.
2013-11-24 19:41:15.882 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: ROLLBACK;
2013-11-24 19:41:15.883 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:41:15.887 sogod[10860] MySQL4 connection established 0x0x7f692d6ac830
2013-11-24 19:41:15.887 sogod[10860] MySQL4 channel 0x0x7f692d8ed560 opened (connection=0x0x7f692d6ac830,sogo_db)
2013-11-24 19:41:15.887 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: BEGIN;
2013-11-24 19:41:15.888 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:15.888 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM  sogo_sessions_folder t1 WHERE t1.c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:41:15.889 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has results, entering fetch-mode.
2013-11-24 19:41:15.889 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: ROLLBACK;
2013-11-24 19:41:15.890 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:15.890 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:41:15.891 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:41:15.892 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: UPDATE sogo_sessions_folder SET c_value = '0OZ4qikKJuVG9n4UolB4ajSKwNUUmMJhAyKgDat+zcDF3zF5YHj/PSKJnBEYWBtTLhi9i+h4CAIYaZn+4dd2iMHyTSw5nw5IczqF2tIltxuaGjg4HrVao+2OE3Q3hTrmXNiVDPnSfTZ4J5XsVnSx3RMDwICJX81sP5HQNBH1BO9ah2aRPCwBmlyhb+Pk/zG3nIZDRNDmwxJmrJ3UCPM7XA==', c_lastseen = 1385350875, c_creationdate = 1385350859, c_id = 'kE+e2W9TTt5DQKr34+MXNg==' WHERE c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:41:15.893 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:41:15.893 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: COMMIT;
2013-11-24 19:41:15.894 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d751770[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d6b1220[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:41:15.898 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter '(objectClass=*)' for attrs 'subschemaSubentry'
2013-11-24 19:41:15.900 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'cn=Subschema' filter '(objectClass=*)' for attrs 'objectclasses'
2013-11-24 19:41:15.910 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(uid=lpeterson)' for attrs 'dn'
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d751770[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d751770[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d8c9f30[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d714a40[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:41:15.925 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(uid=lpeterson)' for attrs 'dn'
2013-11-24 19:41:15.926 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter '(objectclass=*)' for attrs 'supportedCapabilities'
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d8c9f30[NGLdapConnection]> change password - ldap_find_control call failed
2013-11-24 19:41:15.989 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: BEGIN;
2013-11-24 19:41:15.990 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:15.990 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: DELETE FROM sogo_sessions_folder WHERE c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:41:15.991 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:15.991 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: COMMIT;
2013-11-24 19:41:15.992 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:15.993 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: BEGIN;
2013-11-24 19:41:15.993 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:15.994 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM  sogo_sessions_folder t1 WHERE t1.c_id='cP2ggQmYDJCLNGetFWQ3aA==';
2013-11-24 19:41:15.995 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has results, entering fetch-mode.
2013-11-24 19:41:15.995 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: ROLLBACK;
2013-11-24 19:41:15.995 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:15.996 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:41:15.996 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:41:15.996 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: INSERT INTO sogo_sessions_folder (c_value, c_lastseen, c_creationdate, c_id) VALUES ('8RHn255YhFmhq1wiMNTR8FFENYaauun9fE7LADh6a0SnYQXNUiewgL1sDPbaxqgVmPeslaaBbWbMsrstlEw+QhhXQmXRu7oGpE5JuySYVGiWnFm85Nx4sMAud8FKwHc0o/7LdimhKUUWd3ZH0HLURVOMbc4lcGt442VDkb5Sl+Cr/EdD+CI/ObMhfqI4+QHueJ/ef5MGt8xUCgwNNGt8aA==', 1385350875, 1385350875, 'cP2ggQmYDJCLNGetFWQ3aA==');
2013-11-24 19:41:15.997 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:41:15.997 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: COMMIT;
2013-11-24 19:41:15.998 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
Nov 24 19:41:15 sogod [10860]: |SOGo| request took 0.120400 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:15 GMT] "POST /SOGo/so/changePassword HTTP/1.1" 204 0/300 0.124 - - 404K
Nov 24 19:41:17 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail//0/folderINBOX/1/view?noframe=1'
Nov 24 19:41:17 sogod [10860]: <0x0x7f692d08baa0[SOGoWebAuthenticator]> tried wrong password for user 'nWGCr/sq9zbP6yxDU723mTIpUOLz2YiREiu/d1cIAGrEDmj3CAbGtM9YfIbo9Md6qsCslaaBbWbMsrstlEw+QhhXQmXRu7oGpE5JuySYVGiWnFm85Nx4sMAud8FKwHc0o/7LdimhKUUWd3ZH0HLURVOMbc4lcGt442VDkb5Sl+Cr/EdD+CI/ObMhfqI4+QHueJ/ef5MGt8xUCgwNNGt8aA=='!
Nov 24 19:41:17 sogod [10860]: |SOGo| request took 0.014686 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:17 GMT] "POST /SOGo/so/***@mydomain.com/Mail//0/folderINBOX/1/view?noframe=1 HTTP/1.1" 200 1336/0 0.017 2880 53% 36K
Nov 24 19:41:23 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail//0/folderINBOX/expunge'
Nov 24 19:41:23 sogod [10860]: <0x0x7f692d8cf5c0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:23 sogod [10860]: [ERROR] <0x0x7f692d0f3770[LDAPSource]> Could not bind to the LDAP server ldap://ldap-server.mydomain.com:389 (389) using the bind DN: cn=laz peterson,ou=people,dc=mydomain,dc=com
Nov 24 19:41:23 sogod [10860]: [ERROR] <0x0x7f692d0f3770[LDAPSource]> <NSException: 0x7f692d5ee9e0> NAME:LDAPException REASON:operation bind failed: Invalid credentials (0x31) INFO:{login = "cn=laz peterson,ou=people,dc=mydomain,dc=com"; }
Nov 24 19:41:23 sogod [10860]: |SOGo| request took 0.008514 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:23 GMT] "GET /SOGo/so/***@mydomain.com/Mail//0/folderINBOX/expunge HTTP/1.1" 404 104/0 0.011 - - 8K
Nov 24 19:41:23 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo'
2013-11-24 19:41:23.708 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT c_defaults FROM sogo_user_profile WHERE c_uid = 'anonymous';
2013-11-24 19:41:23.708 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has results, entering fetch-mode.
Nov 24 19:41:23 sogod [10860]: |SOGo| request took 0.001684 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:23 GMT] "GET /SOGo HTTP/1.1" 302 0/0 0.003 - - 0
Nov 24 19:41:23 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/'
2013-11-24 19:41:23.721 sogod[10860] WARNING(-[NSNull(misc) count]): called NSNull -count (returns 0) !!!
Nov 24 19:41:23 sogod [10860]: |SOGo|   constructed root-url: /SOGo/
Nov 24 19:41:23 sogod [10860]: |SOGo|   setting root-url in context: /SOGo/
Nov 24 19:41:23 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/
Nov 24 19:41:23 sogod [10860]: |SOGo| request took 0.014939 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:23 GMT] "GET /SOGo/ HTTP/1.1" 200 3598/0 0.017 10765 66% 0
Nov 24 19:41:29 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7e6b20[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7e6b20[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7e6b20[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:41:29 sogod [10860]: SOGoRootPage successful login from '10.0.2.102' for user 'lpeterson' - expire = -1  grace = -1
2013-11-24 19:41:29.105 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: BEGIN;
2013-11-24 19:41:29.106 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:29.106 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM  sogo_sessions_folder t1 WHERE t1.c_id='HNNMu8Umcwy0edv9L69Hwg==';
2013-11-24 19:41:29.107 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has results, entering fetch-mode.
2013-11-24 19:41:29.108 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: ROLLBACK;
2013-11-24 19:41:29.108 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has no results.
2013-11-24 19:41:29.109 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:41:29.110 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:41:29.111 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: INSERT INTO sogo_sessions_folder (c_value, c_lastseen, c_creationdate, c_id) VALUES ('nJ6+UUZp+HZkj4bKfyLKcC1oa7bmB+KRkIGDpizk9GPCpALeGnYTWUl4ESL0iSG0t/uEEgihMkeWc4vtbdAm/7Bbilw1LDTBzCwQ4PDc1udlSDkTZ3IaM1ADtAcciHWP+vSLymJ4cg/dIWXo+KU+yXLETGsmIHu1jMT0gxn23G3IZjtAoMg2Lv+h5MEnUHqpB+/wiGQ/LN4psGDLgx1V3Q==', 1385350889, 1385350889, 'HNNMu8Umcwy0edv9L69Hwg==');
2013-11-24 19:41:29.112 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
2013-11-24 19:41:29.112 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: COMMIT;
2013-11-24 19:41:29.113 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has no results.
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d73cfe0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:41:29.117 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(|(uid=lpeterson)(mail=lpeterson))' for attrs '*'
Nov 24 19:41:29 sogod [10860]: [WARN] <0x0x7f692d02f700[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Nov 24 19:41:29 sogod [10860]: [WARN] <0x0x7f692d02f700[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Nov 24 19:41:29 sogod [10860]: [WARN] <0x0x7f692d02f700[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
2013-11-24 19:41:29.122 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT c_settings FROM sogo_user_profile WHERE c_uid = 'lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org';
2013-11-24 19:41:29.123 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has results, entering fetch-mode.
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.032785 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:29 GMT] "POST /SOGo/connect HTTP/1.1" 200 27/53 0.038 - - 4K
Nov 24 19:41:29 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/lpeterson'
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7abcc0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7abcc0[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7abcc0[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.005915 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:29 GMT] "GET /SOGo/lpeterson HTTP/1.1" 302 0/0 0.008 - - 0
Nov 24 19:41:29 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/lpeterson/view'
2013-11-24 19:41:29.198 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: SELECT c_defaults FROM sogo_user_profile WHERE c_uid = 'lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org';
2013-11-24 19:41:29.199 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has results, entering fetch-mode.
Nov 24 19:41:29 sogod [10860]: |SOGo|   constructed root-url: /SOGo/
Nov 24 19:41:29 sogod [10860]: |SOGo|   setting root-url in context: /SOGo/
Nov 24 19:41:29 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/
Nov 24 19:41:29 sogod [10860]: <0x2D7FFAF0[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/lpeterson/view
  own: /SOGo/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.007694 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:29 GMT] "GET /SOGo/lpeterson/view HTTP/1.1" 302 0/0 0.010 - - 4K
Nov 24 19:41:29 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail'
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.002681 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:29 GMT] "GET /SOGo/so/***@mydomain.com/Mail HTTP/1.1" 302 0/0 0.005 - - 0
Nov 24 19:41:29 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/view'
Nov 24 19:41:29 sogod [10860]: |SOGo|   constructed root-url: /SOGo/
Nov 24 19:41:29 sogod [10860]: |SOGo|   setting root-url in context: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: <0x2D67A3B0[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:29 sogod [10860]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: <0x2D67A3B0[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:29 sogod [10860]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: <0x2D67A3B0[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:29 sogod [10860]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: <0x2D67A3B0[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:29 sogod [10860]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: <0x2D67A3B0[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:29 sogod [10860]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: <0x2D67A3B0[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:29 sogod [10860]: <0x2D82F320[SOGoMailAccounts]:Mail> baseURL: name=Mail (container=SOGoUserFolder)
  container: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail
Nov 24 19:41:29 sogod [10860]: |SOGo|   using root-url from context: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| ROOT baseURL(no container, name=(null)):
  own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: <0x2D67A3B0[SOGoUserFolder]:***@mydomain.com> baseURL: name=lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org (container=SOGo)
  container: /SOGo -- https://sogo.mydomain.com/SOGo/so/***@mydomain.com/Mail/view
  own: /SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.457537 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:29 GMT] "GET /SOGo/so/***@mydomain.com/Mail/view HTTP/1.1" 200 8168/0 0.461 32914 75% 812K
Nov 24 19:41:30 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Calendar/alarmslist?browserTime=1385350890'
2013-11-24 19:41:30.304 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT c_path4 FROM sogo_folder_info WHERE c_path2 = 'lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org' AND c_folder_type = 'Appointment';
2013-11-24 19:41:30.306 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has results, entering fetch-mode.
Nov 24 19:41:30 sogod [10859]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/0/mailboxes'
2013-11-24 19:41:30.313 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: SELECT c_folder_id, c_path, c_location, c_quick_location, c_acl_location, c_folder_type FROM sogo_folder_info WHERE c_path1 = 'Users' AND c_path2 = 'lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org' AND c_path3 = 'Calendar' AND c_path4 = 'personal';
2013-11-24 19:41:30.313 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290>   query has results, entering fetch-mode.
2013-11-24 19:41:30.314 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT b.c_name,a.c_nextalarm,a.c_iscycle FROM sogolpeterso0010c7593f5_quick a, sogolpeterso0010c7593f5 b WHERE (((c_nextalarm <= 1385523690) AND (c_nextalarm >= 1385350890)) OR ((c_nextalarm > 0) AND (c_enddate > 1385350890))) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL);
2013-11-24 19:41:30.315 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830>   query has results, entering fetch-mode.
Nov 24 19:41:30 sogod [10860]: |SOGo| request took 0.013759 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:30 GMT] "POST /SOGo/so/***@mydomain.com/Calendar/alarmslist?browserTime=1385350890 HTTP/1.1" 200 2/0 0.017 - - 0
Nov 24 19:41:30 sogod [10859]: |SOGo| request took 0.326190 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:30 GMT] "POST /SOGo/so/***@mydomain.com/Mail/0/mailboxes HTTP/1.1" 200 402/0 0.329 - - 32K
Nov 24 19:41:30 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/0/folderINBOX/unseenCount'
Nov 24 19:41:30 sogod [10859]: |SOGo| starting method 'POST' on uri '/SOGo/so/lpeterson-3Q2Tfjf0mexWk0Htik3J/***@public.gmane.org/Mail/foldersState'
Nov 24 19:41:30 sogod [10859]: |SOGo| request took 0.004479 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:30 GMT] "POST /SOGo/so/***@mydomain.com/Mail/foldersState HTTP/1.1" 200 0/0 0.007 - - 0
Nov 24 19:41:31 sogod [10860]: |SOGo| request took 0.358216 seconds to execute

Post by Jean Raby

Post by Laz C. Peterson
Yikes.
Then if it shouldn’t matter, I’m sure there’s something else going on here.

I'll test it. But why are you running with a 10 seconds cache expiration? that's
really low.

I think you're running with passwordpolicy enable in sogo, but the
passowrdpolicy overlay is not enabled in openldap.

Just disable password policy in your sogo user source and it will work properly.

Also, you didn't provide your config file, it would have saved us time and
trouble if you had...

(finally, unless you have a good reason to set the cache cleanup interval so
low, you're probably better off keeping it at its default value)
--
users-***@public.gmane.org
https://inverse.ca/sogo/lists
 --
users-***@public.gmane.org
https://inverse.ca/sogo/lists

[Laz C. Peterson]

Further information …

I now have two SOGo servers set up, one is the original that I was having problems with — Server A. The second is a brand new install of Ubuntu 12.04 with latest SOGo — Server B. Both servers use the same LDAP directory and mail servers. Here is some good information.

~~ Test 1 …

Using one browser to connect to both servers (Safari and Firefox in 2 separate tests, but with same results).

User changes password through Server A. Same behavior, cannot access any SOGo pages nor can the user log in. User tries to log in through Server B using same browser, authentication is fine and SOGo is fine.

~~ Test 2 …

Two separate MySQL databases, and two servers, same results as previous test.

User can not log in to the server that the password was changed on, but has no problem logging into the other server.

~~ Test 3 …

Two computers, two servers. User changes password on Server A, cannot continue using SOGo nor log in. Server says “successful login” but stays at login page. User can access Server B no problem with new password.

Second computer, user can access Server B with no problems using new password, but suffers the same issue with Server A as the first computer.

~~ Test 4 …

One computer, one server. User changes password, cannot log in and cannot use SOGo. SOGo server is restarted (service sogo restart). User still cannot log in. Other server works fine.

~~ Test 5 … IMPORTANT!

If I change “SOGoCacheCleanupInterval” to 1 on Server A, which you have advised is not necessary and possibly counterproductive to SOGo’s functionality, it is extremely difficult for me to recreate the problem. With over a dozen tests in a row, I was only able to fail one time, and it was connecting through Server B.

~~~~ End tests ...

This must be some sort of a caching problem with SOGo inside the database. I cannot pinpoint the source, as I do not understand how SOGo authenticates or stores the account/login information inside the database. But it is apparent that the problem is not the database itself, nor the local browser’s cookies. The issue, with SOGoCacheCleanupInterval set default, “sticks” with the server for an undetermined amount of time, usually a couple minutes.

I can confirm that MySQL, LDAP, and IMAP servers are all functioning properly, and that they are all authenticating immediately using the new password.

Please help. I would love to figure out how to resolve this issue, and I am more than willing to provide any information that might help.

Thank you.
~Laz

Here is the most detailed log that I can provide for you. I truly hope this helps. Thanks.
Nov 24 19:40:59 sogod [10859]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d2e7940[SOGoCache]> Cache cleanup interval set every 5.000000 seconds
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d2e7940[SOGoCache]> Using host(s) 'localhost' as server(s)
2013-11-24 19:40:59.667 sogod[10859] Note(SoObject): SoDebugKeyLookup is enabled!
2013-11-24 19:40:59.667 sogod[10859] Note(SoObject): SoDebugBaseURL is enabled!
2013-11-24 19:40:59.668 sogod[10859] Note(SoObject): relative base URLs are enabled.
2013-11-24 19:40:59.674 sogod[10859] ERROR(-[NGBundleManager bundleWithPath:]): could not create bundle for path: '/usr/share/GNUstep/Libraries/gnustep-base/Versions/1.22/Resources/SSL.bundle'
2013-11-24 19:40:59.681 sogod[10859] WOxElemBuilder: could not locate builders: WOxExtElemBuilder,WOxExtElemBuilder
2013-11-24 19:40:59.682 sogod[10859] WOCompoundElement: pool embedding is on.
2013-11-24 19:40:59.682 sogod[10859] WOCompoundElement: id logging is on.
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d6380b0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d623310[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:40:59.692 sogod[10859] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter '(objectClass=*)' for attrs 'subschemaSubentry'
2013-11-24 19:40:59.693 sogod[10859] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'cn=Subschema' filter '(objectClass=*)' for attrs 'objectclasses'
2013-11-24 19:40:59.700 sogod[10859] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(uid=lpeterson)' for attrs 'dn'
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d6380b0[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d6380b0[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:40:59 sogod [10859]: SOGoRootPage successful login from '10.0.2.102' for user 'lpeterson' - expire = -1 grace = -1
2013-11-24 19:40:59.709 sogod[10859] MySQL4 connection established 0x0x7f692d694210
2013-11-24 19:40:59.710 sogod[10859] MySQL4 channel 0x0x7f692d6477c0 opened (connection=0x0x7f692d694210,sogo_db)
2013-11-24 19:40:59.710 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: BEGIN;
2013-11-24 19:40:59.711 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> query has no results.
2013-11-24 19:40:59.712 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM sogo_sessions_folder t1 WHERE t1.c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:40:59.713 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> query has results, entering fetch-mode.
2013-11-24 19:40:59.713 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: ROLLBACK;
2013-11-24 19:40:59.714 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> query has no results.
2013-11-24 19:40:59.714 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:40:59.716 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:40:59.716 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: INSERT INTO sogo_sessions_folder (c_value, c_lastseen, c_creationdate, c_id) VALUES ('0OZ4qikKJuVG9n4UolB4ajSKwNUUmMJhAyKgDat+zcDF3zF5YHj/PSKJnBEYWBtTLhi9i+h4CAIYaZn+4dd2iMHyTSw5nw5IczqF2tIltxuaGjg4HrVao+2OE3Q3hTrmXNiVDPnSfTZ4J5XsVnSx3RMDwICJX81sP5HQNBH1BO9ah2aRPCwBmlyhb+Pk/zG3nIZDRNDmwxJmrJ3UCPM7XA==', 1385350859, 1385350859, 'kE+e2W9TTt5DQKr34+MXNg==');
2013-11-24 19:40:59.717 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:40:59.718 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: COMMIT;
2013-11-24 19:40:59.718 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d6c7740[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:40:59.722 sogod[10859] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(|(uid=lpeterson)(mail=lpeterson))' for attrs '*'
Nov 24 19:40:59 sogod [10859]: [WARN] <0x0x7f692d7077e0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Nov 24 19:40:59 sogod [10859]: [WARN] <0x0x7f692d7077e0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Nov 24 19:40:59 sogod [10859]: [WARN] <0x0x7f692d7077e0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
2013-11-24 19:40:59.729 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> query has results, entering fetch-mode.
Nov 24 19:40:59 sogod [10859]: |SOGo| request took 0.066954 seconds to execute
2013-11-24 19:40:59.732 sogod[10859] Note: Using UTF-8 as URL encoding in NGExtensions.
10.0.2.102 - - [24/Nov/2013:19:40:59 GMT] "POST /SOGo/connect HTTP/1.1" 200 27/53 0.073 - - 3M
Nov 24 19:40:59 sogod [10859]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson'
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d596e00[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d596e00[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:40:59 sogod [10859]: <0x0x7f692d596e00[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:40:59 sogod [10859]: |SOGo| request took 0.007301 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:40:59 GMT] "GET /SOGo/so/lpeterson HTTP/1.1" 302 0/0 0.010 - - 36K
Nov 24 19:40:59 sogod [10859]: |SOGo| starting method 'GET' on uri '/SOGo/so/lpeterson/view'
2013-11-24 19:40:59.920 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has results, entering fetch-mode.
Nov 24 19:40:59 sogod [10859]: |SOGo| constructed root-url: /SOGo/
Nov 24 19:40:59 sogod [10859]: |SOGo| setting root-url in context: /SOGo/so/
own: /SOGo/so/
container: /SOGo -- https://sogo.mydomain.com/SOGo/so/lpeterson/view
Nov 24 19:40:59 sogod [10859]: |SOGo| request took 0.007516 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:40:59 GMT] "GET /SOGo/so/lpeterson/view HTTP/1.1" 302 0/0 0.010 - - 8K
Nov 24 19:40:59 sogod [10859]: |SOGo| request took 0.002355 seconds to execute
Nov 24 19:40:59 sogod [10859]: |SOGo| constructed root-url: /SOGo/
Nov 24 19:40:59 sogod [10859]: |SOGo| setting root-url in context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:40:59 sogod [10859]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
2013-11-24 19:41:00.007 sogod[10859] WARNING: IMAP4 connection pooling is disabled!
2013-11-24 19:41:00.166 sogod[10859] Note(NGImap4Connection): using '/' as the IMAP4 folder separator.
Nov 24 19:41:00 sogod [10859]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: <0x2D638F20[SOGoMailAccounts]:Mail> baseURL: name=Mail (container=SOGoUserFolder)
Nov 24 19:41:00 sogod [10859]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:00 sogod [10859]: |SOGo| request took 0.468720 seconds to execute
2013-11-24 19:41:00.871 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> query has results, entering fetch-mode.
2013-11-24 19:41:00.875 sogod[10859] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has results, entering fetch-mode.
2013-11-24 19:41:00.876 sogod[10859] <MySQL4Channel[0x0x7f692d6477c0] connection=0x0x7f692d694210> SQL: SELECT b.c_name,a.c_nextalarm,a.c_iscycle FROM sogolpeterso0010c7593f5_quick a, sogolpeterso0010c7593f5 b WHERE (((c_nextalarm <= 1385523660) AND (c_nextalarm >= 1385350860)) OR ((c_nextalarm > 0) AND (c_enddate > 1385350860))) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL);
2013-11-24 19:41:00.881 sogod[10860] Note: Using UTF-8 as URL encoding in NGExtensions.
Nov 24 19:41:00 sogod [10859]: |SOGo| request took 0.014768 seconds to execute
Nov 24 19:41:00 sogod [10860]: <0x0x7f692d2d0990[SOGoCache]> Cache cleanup interval set every 5.000000 seconds
2013-11-24 19:41:00.889 sogod[10860] Note(SoObject): SoDebugKeyLookup is enabled!
2013-11-24 19:41:00.889 sogod[10860] Note(SoObject): SoDebugBaseURL is enabled!
2013-11-24 19:41:00.889 sogod[10860] Note(SoObject): relative base URLs are enabled.
2013-11-24 19:41:00.893 sogod[10860] WARNING: IMAP4 connection pooling is disabled!
2013-11-24 19:41:01.044 sogod[10860] Note(NGImap4Connection): using '/' as the IMAP4 folder separator.
Nov 24 19:41:01 sogod [10860]: |SOGo| request took 0.323621 seconds to execute
Nov 24 19:41:01 sogod [10859]: |SOGo| request took 0.007251 seconds to execute
Nov 24 19:41:01 sogod [10860]: |SOGo| request took 0.358742 seconds to execute
2013-11-24 19:41:03.099 sogod[10860] ERROR(-[NGBundleManager bundleWithPath:]): could not create bundle for path: '/usr/share/GNUstep/Libraries/gnustep-base/Versions/1.22/Resources/SSL.bundle'
2013-11-24 19:41:03.115 sogod[10860] WOxElemBuilder: could not locate builders: WOxExtElemBuilder,WOxExtElemBuilder
2013-11-24 19:41:03.115 sogod[10860] WOCompoundElement: pool embedding is on.
2013-11-24 19:41:03.115 sogod[10860] WOCompoundElement: id logging is on.
Nov 24 19:41:03 sogod [10860]: |SOGo| constructed root-url: /SOGo/
Nov 24 19:41:03 sogod [10860]: |SOGo| setting root-url in context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:03 sogod [10860]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:03 sogod [10860]: |SOGo| request took 0.089552 seconds to execute
Nov 24 19:41:15 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/so/changePassword'
2013-11-24 19:41:15.879 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:41:15.880 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:41:15.881 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM sogo_sessions_folder t1 WHERE t1.c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:41:15.882 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has results, entering fetch-mode.
2013-11-24 19:41:15.882 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: ROLLBACK;
2013-11-24 19:41:15.883 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:41:15.887 sogod[10860] MySQL4 connection established 0x0x7f692d6ac830
2013-11-24 19:41:15.887 sogod[10860] MySQL4 channel 0x0x7f692d8ed560 opened (connection=0x0x7f692d6ac830,sogo_db)
2013-11-24 19:41:15.887 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: BEGIN;
2013-11-24 19:41:15.888 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:15.888 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM sogo_sessions_folder t1 WHERE t1.c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:41:15.889 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has results, entering fetch-mode.
2013-11-24 19:41:15.889 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: ROLLBACK;
2013-11-24 19:41:15.890 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:15.890 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:41:15.891 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:41:15.892 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: UPDATE sogo_sessions_folder SET c_value = '0OZ4qikKJuVG9n4UolB4ajSKwNUUmMJhAyKgDat+zcDF3zF5YHj/PSKJnBEYWBtTLhi9i+h4CAIYaZn+4dd2iMHyTSw5nw5IczqF2tIltxuaGjg4HrVao+2OE3Q3hTrmXNiVDPnSfTZ4J5XsVnSx3RMDwICJX81sP5HQNBH1BO9ah2aRPCwBmlyhb+Pk/zG3nIZDRNDmwxJmrJ3UCPM7XA==', c_lastseen = 1385350875, c_creationdate = 1385350859, c_id = 'kE+e2W9TTt5DQKr34+MXNg==' WHERE c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:41:15.893 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:41:15.893 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: COMMIT;
2013-11-24 19:41:15.894 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d751770[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d6b1220[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:41:15.898 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter '(objectClass=*)' for attrs 'subschemaSubentry'
2013-11-24 19:41:15.900 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'cn=Subschema' filter '(objectClass=*)' for attrs 'objectclasses'
2013-11-24 19:41:15.910 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(uid=lpeterson)' for attrs 'dn'
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d751770[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d751770[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d8c9f30[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d714a40[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:41:15.925 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(uid=lpeterson)' for attrs 'dn'
2013-11-24 19:41:15.926 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base '' filter '(objectclass=*)' for attrs 'supportedCapabilities'
Nov 24 19:41:15 sogod [10860]: <0x0x7f692d8c9f30[NGLdapConnection]> change password - ldap_find_control call failed
2013-11-24 19:41:15.989 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: BEGIN;
2013-11-24 19:41:15.990 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:15.990 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: DELETE FROM sogo_sessions_folder WHERE c_id='kE+e2W9TTt5DQKr34+MXNg==';
2013-11-24 19:41:15.991 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:15.991 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: COMMIT;
2013-11-24 19:41:15.992 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:15.993 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: BEGIN;
2013-11-24 19:41:15.993 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:15.994 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM sogo_sessions_folder t1 WHERE t1.c_id='cP2ggQmYDJCLNGetFWQ3aA==';
2013-11-24 19:41:15.995 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has results, entering fetch-mode.
2013-11-24 19:41:15.995 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: ROLLBACK;
2013-11-24 19:41:15.995 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:15.996 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:41:15.996 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:41:15.996 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: INSERT INTO sogo_sessions_folder (c_value, c_lastseen, c_creationdate, c_id) VALUES ('8RHn255YhFmhq1wiMNTR8FFENYaauun9fE7LADh6a0SnYQXNUiewgL1sDPbaxqgVmPeslaaBbWbMsrstlEw+QhhXQmXRu7oGpE5JuySYVGiWnFm85Nx4sMAud8FKwHc0o/7LdimhKUUWd3ZH0HLURVOMbc4lcGt442VDkb5Sl+Cr/EdD+CI/ObMhfqI4+QHueJ/ef5MGt8xUCgwNNGt8aA==', 1385350875, 1385350875, 'cP2ggQmYDJCLNGetFWQ3aA==');
2013-11-24 19:41:15.997 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:41:15.997 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: COMMIT;
2013-11-24 19:41:15.998 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
Nov 24 19:41:15 sogod [10860]: |SOGo| request took 0.120400 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:15 GMT] "POST /SOGo/so/changePassword HTTP/1.1" 204 0/300 0.124 - - 404K
Nov 24 19:41:17 sogod [10860]: <0x0x7f692d08baa0[SOGoWebAuthenticator]> tried wrong password for user 'nWGCr/sq9zbP6yxDU723mTIpUOLz2YiREiu/d1cIAGrEDmj3CAbGtM9YfIbo9Md6qsCslaaBbWbMsrstlEw+QhhXQmXRu7oGpE5JuySYVGiWnFm85Nx4sMAud8FKwHc0o/7LdimhKUUWd3ZH0HLURVOMbc4lcGt442VDkb5Sl+Cr/EdD+CI/ObMhfqI4+QHueJ/ef5MGt8xUCgwNNGt8aA=='!
Nov 24 19:41:17 sogod [10860]: |SOGo| request took 0.014686 seconds to execute
Nov 24 19:41:23 sogod [10860]: <0x0x7f692d8cf5c0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:23 sogod [10860]: [ERROR] <0x0x7f692d0f3770[LDAPSource]> Could not bind to the LDAP server ldap://ldap-server.mydomain.com:389 (389) using the bind DN: cn=laz peterson,ou=people,dc=mydomain,dc=com
Nov 24 19:41:23 sogod [10860]: [ERROR] <0x0x7f692d0f3770[LDAPSource]> <NSException: 0x7f692d5ee9e0> NAME:LDAPException REASON:operation bind failed: Invalid credentials (0x31) INFO:{login = "cn=laz peterson,ou=people,dc=mydomain,dc=com"; }
Nov 24 19:41:23 sogod [10860]: |SOGo| request took 0.008514 seconds to execute
Nov 24 19:41:23 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo'
2013-11-24 19:41:23.708 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT c_defaults FROM sogo_user_profile WHERE c_uid = 'anonymous';
2013-11-24 19:41:23.708 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has results, entering fetch-mode.
Nov 24 19:41:23 sogod [10860]: |SOGo| request took 0.001684 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:23 GMT] "GET /SOGo HTTP/1.1" 302 0/0 0.003 - - 0
Nov 24 19:41:23 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/'
2013-11-24 19:41:23.721 sogod[10860] WARNING(-[NSNull(misc) count]): called NSNull -count (returns 0) !!!
Nov 24 19:41:23 sogod [10860]: |SOGo| constructed root-url: /SOGo/
Nov 24 19:41:23 sogod [10860]: |SOGo| setting root-url in context: /SOGo/
own: /SOGo/
Nov 24 19:41:23 sogod [10860]: |SOGo| request took 0.014939 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:23 GMT] "GET /SOGo/ HTTP/1.1" 200 3598/0 0.017 10765 66% 0
Nov 24 19:41:29 sogod [10860]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7e6b20[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7e6b20[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7e6b20[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:41:29 sogod [10860]: SOGoRootPage successful login from '10.0.2.102' for user 'lpeterson' - expire = -1 grace = -1
2013-11-24 19:41:29.105 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: BEGIN;
2013-11-24 19:41:29.106 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:29.106 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT t1.c_creationdate, t1.c_id, t1.c_lastseen, t1.c_value FROM sogo_sessions_folder t1 WHERE t1.c_id='HNNMu8Umcwy0edv9L69Hwg==';
2013-11-24 19:41:29.107 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has results, entering fetch-mode.
2013-11-24 19:41:29.108 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: ROLLBACK;
2013-11-24 19:41:29.108 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has no results.
2013-11-24 19:41:29.109 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: BEGIN;
2013-11-24 19:41:29.110 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:41:29.111 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: INSERT INTO sogo_sessions_folder (c_value, c_lastseen, c_creationdate, c_id) VALUES ('nJ6+UUZp+HZkj4bKfyLKcC1oa7bmB+KRkIGDpizk9GPCpALeGnYTWUl4ESL0iSG0t/uEEgihMkeWc4vtbdAm/7Bbilw1LDTBzCwQ4PDc1udlSDkTZ3IaM1ADtAcciHWP+vSLymJ4cg/dIWXo+KU+yXLETGsmIHu1jMT0gxn23G3IZjtAoMg2Lv+h5MEnUHqpB+/wiGQ/LN4psGDLgx1V3Q==', 1385350889, 1385350889, 'HNNMu8Umcwy0edv9L69Hwg==');
2013-11-24 19:41:29.112 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
2013-11-24 19:41:29.112 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> SQL: COMMIT;
2013-11-24 19:41:29.113 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has no results.
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d73cfe0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
2013-11-24 19:41:29.117 sogod[10860] -[NGLdapConnection _searchAtBaseDN:qualifier:attributes:scope:]: search at base 'ou=people,dc=mydomain,dc=com' filter '(|(uid=lpeterson)(mail=lpeterson))' for attrs '*'
Nov 24 19:41:29 sogod [10860]: [WARN] <0x0x7f692d02f700[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Nov 24 19:41:29 sogod [10860]: [WARN] <0x0x7f692d02f700[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Nov 24 19:41:29 sogod [10860]: [WARN] <0x0x7f692d02f700[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
2013-11-24 19:41:29.123 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has results, entering fetch-mode.
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.032785 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:29 GMT] "POST /SOGo/connect HTTP/1.1" 200 27/53 0.038 - - 4K
Nov 24 19:41:29 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/lpeterson'
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7abcc0[NGLdapConnection]> Using ldap_initialize for LDAP URL: ldap://ldap-server.mydomain.com:389
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7abcc0[NGLdapConnection]> bind - ldap_result call result: 97
Nov 24 19:41:29 sogod [10860]: <0x0x7f692d7abcc0[NGLdapConnection]> bind - policy values: -1 -1 65535 - bound: 1
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.005915 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:29 GMT] "GET /SOGo/lpeterson HTTP/1.1" 302 0/0 0.008 - - 0
Nov 24 19:41:29 sogod [10860]: |SOGo| starting method 'GET' on uri '/SOGo/lpeterson/view'
2013-11-24 19:41:29.199 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has results, entering fetch-mode.
Nov 24 19:41:29 sogod [10860]: |SOGo| constructed root-url: /SOGo/
Nov 24 19:41:29 sogod [10860]: |SOGo| setting root-url in context: /SOGo/
own: /SOGo/
container: /SOGo -- https://sogo.mydomain.com/SOGo/lpeterson/view
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.007694 seconds to execute
10.0.2.102 - - [24/Nov/2013:19:41:29 GMT] "GET /SOGo/lpeterson/view HTTP/1.1" 302 0/0 0.010 - - 4K
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.002681 seconds to execute
Nov 24 19:41:29 sogod [10860]: |SOGo| constructed root-url: /SOGo/
Nov 24 19:41:29 sogod [10860]: |SOGo| setting root-url in context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: <0x2D82F320[SOGoMailAccounts]:Mail> baseURL: name=Mail (container=SOGoUserFolder)
Nov 24 19:41:29 sogod [10860]: |SOGo| using root-url from context: /SOGo/so/
own: /SOGo/so/
Nov 24 19:41:29 sogod [10860]: |SOGo| request took 0.457537 seconds to execute
2013-11-24 19:41:30.306 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has results, entering fetch-mode.
2013-11-24 19:41:30.313 sogod[10860] <MySQL4Channel[0x0x7f692d330960] connection=0x0x7f692d323290> query has results, entering fetch-mode.
2013-11-24 19:41:30.314 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> SQL: SELECT b.c_name,a.c_nextalarm,a.c_iscycle FROM sogolpeterso0010c7593f5_quick a, sogolpeterso0010c7593f5 b WHERE (((c_nextalarm <= 1385523690) AND (c_nextalarm >= 1385350890)) OR ((c_nextalarm > 0) AND (c_enddate > 1385350890))) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL);
2013-11-24 19:41:30.315 sogod[10860] <MySQL4Channel[0x0x7f692d8ed560] connection=0x0x7f692d6ac830> query has results, entering fetch-mode.
Nov 24 19:41:30 sogod [10860]: |SOGo| request took 0.013759 seconds to execute
Nov 24 19:41:30 sogod [10859]: |SOGo| request took 0.326190 seconds to execute
Nov 24 19:41:30 sogod [10859]: |SOGo| request took 0.004479 seconds to execute
Nov 24 19:41:31 sogod [10860]: |SOGo| request took 0.358216 seconds to execute

Post by Jean Raby

Post by Laz C. Peterson
Yikes.
Then if it shouldn’t matter, I’m sure there’s something else going on here.

I'll test it. But why are you running with a 10 seconds cache expiration? that's
really low.

I think you're running with passwordpolicy enable in sogo, but the
passowrdpolicy overlay is not enabled in openldap.
Just disable password policy in your sogo user source and it will work properly.
Also, you didn't provide your config file, it would have saved us time and
trouble if you had...
(finally, unless you have a good reason to set the cache cleanup interval so
low, you're probably better off keeping it at its default value)
--
https://inverse.ca/sogo/lists
--
https://inverse.ca/sogo/lists

[Laz C. Peterson]

Jean, hello.

You are correct, it does work just fine as you have designed. Which browser are you using?

There was nothing abnormal in the logs, neither on the LDAP server nor the SOGo server. All looks good. This is not debug logging, however.

Maybe you can try reproducing the problem. I have been primarily using FireFox lately, which is the browser that is not acting properly. After I sent my initial message, I decided to try Safari just for fun, and that worked *perfectly*.

If you don’t use FireFox, would you mind trying that out and see if you get the same result?

I’m a little confused as to why it would act that way. Possibly it is an issue on my specific workstation’s install of FireFox?

Thanks for your response. Please let me know if there is any more information I can get for you.
~Laz

Post by Jean Raby

Post by Laz C. Peterson
Can someone please fill me in on the expected behavior of SOGo after the user changes their password through preferences?
My users, who can change their passwords just fine through the preferences, get stuck in SOGo after changing the password. It appears as if they are still logged in, but if they go to write a new message or click on a different feature (such as Calendar), they are presented with a login box. (At this point, they can log in fine using their new password.)
I want to confirm that this is by design, or if there is something I need to look into. It seems that either the user should not have to relog in at all, or that the user should immediately be logged off and presented with a new login screen.

Can you explain or post your sogo configuration?
Anything relevant in the logs?
I just tested this with sogo using openldap as its auth backend and it works as designed. That is: when I change my password, I can still use sogo without having to log back in.

Post by Laz C. Peterson
Thanks for any help.
~Laz--

--
https://inverse.ca/sogo/lists

[Laz C. Peterson]

I might add that the behavior I see in Safari works as I would expect — changing password simply changes password and leaves all other functions working as they were, including SOGo, email and calendar.

FireFox, on the other hand, exhibits the behavior where the authentication gets broken and the website does not display or operate properly until user logs back in.

Thanks for any help.
~Laz

Post by Laz C. Peterson
Can someone please fill me in on the expected behavior of SOGo after the user changes their password through preferences?
My users, who can change their passwords just fine through the preferences, get stuck in SOGo after changing the password. It appears as if they are still logged in, but if they go to write a new message or click on a different feature (such as Calendar), they are presented with a login box. (At this point, they can log in fine using their new password.)
I want to confirm that this is by design, or if there is something I need to look into. It seems that either the user should not have to relog in at all, or that the user should immediately be logged off and presented with a new login screen.
Thanks for any help.
~Laz--
https://inverse.ca/sogo/lists