Very Long Login/Authentication Time

[schalliol]

On a Dual 1.8GHz G4 OS X server it takes literally 5 or more MINUTES to authenticate at local log-in. The login window text input locations go grey, as a lock-out, as you expect, but it should only take a 1/2 second or so to authenticate under normal circumstances. If I try to log in through system preferences to make adjustments, I never get beyond the authentication screen, requiring a force quit or restart. Otherwise, the server operates normally. This is just a test server, so it’s not a huge problem at the moment, but this is obviously a big problem as far as the machine goes. Ideas? Thanks!

[rmleonard]

Several Questions
What version of OS?
Is the unit bound to any directory services?

once you get in – what do the log files show?
(specifically – /var/log/system.log)

More Info Please!

[deemery]

The other thing to check is load average. I really like the iStat Pro widget for this kind of ‘what’s happening right now’ kind of monitoring (if your server has a ‘head’ on it.)

For what it’s worth, I’ve noticed the load average on my G4/933 running Tiger Server, now serving a new Intel iMac, has jumped. What I did to help manage this was run -no active windows- on the server. (When iTunes, which runs 24×7 on my G4, has its window open, that added 10% of the load average to keep the iTunes window up-to-date. The Finder did similar things for directories.)

dave

[schalliol]

Thanks for the quick reply. Here are the responses to your questions:

Server Version: 10.5.1 (was clean install with 10.5.0 server).
Binding To Directory Services: None
Log Files:

11/30/07 1:44:06 PM org.clamav.clamd[44] Mail: Recursion level limit set to 64. 
11/30/07 1:44:06 PM org.clamav.clamd[44] OLE2 support enabled. 
11/30/07 1:44:06 PM org.clamav.clamd[44] PDF support disabled. 
11/30/07 1:44:06 PM org.clamav.clamd[44] HTML support enabled. 
11/30/07 1:44:06 PM org.clamav.clamd[44] Self checking every 1800 seconds. 
11/30/07 1:44:06 PM org.clamav.clamd[44] Set stacksize to 1048576 
11/30/07 1:44:06 PM com.apple.launchd[1] (edu.cmu.andrew.cyrus.master[182]) Stray process with PGID equal to this dead job: PID 184 PPID 1 ctl_cyrusdb 
11/30/07 1:44:06 PM com.apple.launchd[1] (edu.cmu.andrew.cyrus.master[182]) Exited abnormally: User defined signal 1 
11/30/07 1:44:06 PM com.apple.launchd[1] (edu.cmu.andrew.cyrus.master) Throttling respawn: Will start in 10 seconds 
11/30/07 1:44:07 PM com.apple.KerberosAutoConfig[188] Couldn't find KerberosClient config record 
11/30/07 1:44:13 PM com.apple.KerberosAutoConfig[202] Kerberos configuration is up to date 
11/30/07 1:50:33 PM com.apple.launchd[1] (com.apple.mail_group_expander) Throttling respawn: Will start in 9 seconds 
11/30/07 1:50:34 PM com.apple.launchd[1] (com.apple.ScreenSharing.server[161]) Exited: Terminated 
11/30/07 1:50:34 PM com.apple.launchd[1] (com.apple.UserEventAgent-LoginWindow[162]) Exited: Terminated 
11/30/07 1:50:38 PM Dock[321] _DESCRegisterDockExtraClient failed 268435459 
11/30/07 1:50:40 PM Dock[321] Could not create a directory for <DOCKFolderTile: 0x22eb90> error = Error Domain=NSOSStatusErrorDomain Code=-35 "Operation could not be completed. (OSStatus error -35.)" (no such volume)

I looked up edu.cmu.andrew.cyrus.master and found this Apple forum discussion, which suggests mail may be to blame, but I don’t have accounts set up beyond the default system accounts and server admin says mail is off (which I want it to be).

I installed iStat Menus and the load of CPU and Memory is quite low.

Do you have any thoughts from these notes? Thanks for looking into this for me!

[rmleonard]

does the user’s home directory exist?
What is the OD-MCX setting for the user who us logging in?
is the user set to be a mobile user? a network user? a local user?

[schalliol]

rmleonard wrote:

does the user’s home directory exist?
What is the OD-MCX setting for the user who us logging in?
is the user set to be a mobile user? a network user? a local user?

The user logging in is set as the principal admin, as set up in the initial install. Listed as Admin, Network, Manager. This is being done locally with no modifications from the initial install for the user. The user doesn’t even have any documents.

This is from the system.log. Previously I provided the console:

Nov 30 13:43:59 IIPI-OS-X-Server loginwindow[63]: Login Window Started Security Agent
Nov 30 13:44:05 IIPI-OS-X-Server org.clamav.clamd[44]: Loaded 171949 signatures.
Nov 30 13:44:06 IIPI-OS-X-Server com.apple.launchd[1] (edu.cmu.andrew.cyrus.master[49]): Stray process with PGID equal to this dead job: PID 100 PPID 1 ctl_cyrusdb
Nov 30 13:44:06 IIPI-OS-X-Server com.apple.launchd[1] (edu.cmu.andrew.cyrus.master[49]): Exited abnormally: User defined signal 1
Nov 30 13:44:06 IIPI-OS-X-Server servermgrd[58]: servermgr_calendar: created default calendar virtual host
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Unix socket file /var/amavis/clamd
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Setting connection queue length to 15
Nov 30 13:44:06 IIPI-OS-X-Server master[182]: process started
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Archive: Archived file size limit set to 10485760 bytes.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Archive: Recursion level limit set to 8.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Archive: Files limit set to 1000.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Archive: Compression ratio limit set to 250.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Archive support enabled.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Algorithmic detection enabled.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Portable Executable support enabled.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: ELF support enabled.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Mail files support enabled.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Mail: Recursion level limit set to 64.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: OLE2 support enabled.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: PDF support disabled.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: HTML support enabled.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Self checking every 1800 seconds.
Nov 30 13:44:06 IIPI-OS-X-Server org.clamav.clamd[44]: Set stacksize to 1048576
Nov 30 13:44:06 IIPI-OS-X-Server com.apple.launchd[1] (edu.cmu.andrew.cyrus.master[182]): Stray process with PGID equal to this dead job: PID 184 PPID 1 ctl_cyrusdb
Nov 30 13:44:06 IIPI-OS-X-Server com.apple.launchd[1] (edu.cmu.andrew.cyrus.master[182]): Exited abnormally: User defined signal 1
Nov 30 13:44:06 IIPI-OS-X-Server com.apple.launchd[1] (edu.cmu.andrew.cyrus.master): Throttling respawn: Will start in 10 seconds
Nov 30 13:44:07 IIPI-OS-X-Server com.apple.KerberosAutoConfig[188]: Couldn't find KerberosClient config record
Nov 30 13:44:13 IIPI-OS-X-Server com.apple.KerberosAutoConfig[202]: Kerberos configuration is up to date
Nov 30 13:44:16 IIPI-OS-X-Server master[206]: process started
Nov 30 13:44:34 IIPI-OS-X-Server ctl_cyrusdb[207]: DBERROR db4: unable to join the environment
Nov 30 13:44:36 IIPI-OS-X-Server ctl_cyrusdb[207]: verifying cyrus databases
Nov 30 13:44:36 IIPI-OS-X-Server ctl_cyrusdb[207]: skiplist: recovered /var/imap/mailboxes.db (0 records, 144 bytes) in 0 seconds
Nov 30 13:44:36 IIPI-OS-X-Server ctl_cyrusdb[207]: skiplist: recovered /var/imap/annotations.db (0 records, 144 bytes) in 0 seconds
Nov 30 13:44:46 IIPI-OS-X-Server ctl_cyrusdb[207]: done verifying cyrus databases
Nov 30 13:44:46 IIPI-OS-X-Server master[206]: Cyrus POP/IMAP Server v2.3.8 ready for work
Nov 30 13:44:46 IIPI-OS-X-Server ctl_cyrusdb[225]: checkpointing cyrus databases
Nov 30 13:44:46 IIPI-OS-X-Server ctl_cyrusdb[225]: done checkpointing cyrus databases
Nov 30 13:45:48 IIPI-OS-X-Server authorizationhost[167]: MechanismInvoke 0x14d690 retainCount 2
Nov 30 13:45:48 IIPI-OS-X-Server SecurityAgent[168]: MechanismInvoke 0x103e50 retainCount 1
                  -- FIVE MINUTE GAP --
Nov 30 13:50:30 IIPI-OS-X-Server DirectoryService[23]: GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (Server not found in Kerberos database)
Nov 30 13:50:32 IIPI-OS-X-Server SecurityAgent[168]: NSSecureTextFieldCell detected a field editor ((null)) that is not a NSTextView subclass designed to work with the cell. Ignoring...
Nov 30 13:50:33 IIPI-OS-X-Server com.apple.launchd[1] (com.apple.mail_group_expander): Throttling respawn: Will start in 9 seconds
Nov 30 13:50:33 IIPI-OS-X-Server SecurityAgent[168]: MechanismDestroy 0x103e50 retainCount 1
Nov 30 13:50:33 IIPI-OS-X-Server loginwindow[63]: Login Window - Returned from Security Agent
Nov 30 13:50:33 IIPI-OS-X-Server authorizationhost[167]: MechanismDestroy 0x14d690 retainCount 2
Nov 30 13:50:34 IIPI-OS-X-Server loginwindow[63]: USER_PROCESS: 63 console
Nov 30 13:50:34 IIPI-OS-X-Server com.apple.launchd[1] (com.apple.ScreenSharing.server[161]): Exited: Terminated
Nov 30 13:50:34 IIPI-OS-X-Server com.apple.launchd[1] (com.apple.UserEventAgent-LoginWindow[162]): Exited: Terminated
Nov 30 13:50:38 IIPI-OS-X-Server Dock[321]: _DESCRegisterDockExtraClient failed 268435459
Nov 30 13:50:40 IIPI-OS-X-Server Dock[321]: Could not create a directory for <DOCKFolderTile: 0x22eb90> error = Error Domain=NSOSStatusErrorDomain Code=-35 "Operation could not be completed. (OSStatus error -35.)" (no such volume)
Nov 30 13:50:41 IIPI-OS-X-Server /System/Library/CoreServices/coreservicesd[105]: SFLSharePointsEntry::CreateDSRecord: dsCreateRecordAndOpen(Backups) returned -14135
Nov 30 13:50:41 IIPI-OS-X-Server /System/Library/CoreServices/coreservicesd[105]: SFLSharePointsEntry::CreateDSRecord: dsCreateRecordAndOpen(Groups) returned -14135
Nov 30 13:50:41 IIPI-OS-X-Server /System/Library/CoreServices/coreservicesd[105]: SFLSharePointsEntry::CreateDSRecord: dsCreateRecordAndOpen(Public) returned -14135

I checked the console and system log before and after authenticating into the system preferences account prefpane to make changes and didn’t see anything posted in that process, although it took a few minutes for that operation to complete. I’ll try the same thing while looking at activity monitor. edit: I don’t see anything really happening when checking activity monitor

Man, you guys are fast and really being helpful by the questions you ask thus far. I’m really going to have to hang out here!

[Author]

Posts