SMTP Relay Hang
Posted: Tue Dec 13, 2005 1:41 pm
by wheelc
Hello,
I am having an issue with the latest version of SCALIX community edition. The problem:
I can not use SWA to send e-mail to the server. All other methods work including scalix connect, IMPA, and direct via smtp using outlook express.
The moment a user tries to use SWA and send an email it hangs the service. No other emails are sent following that point.
Any ideas.
cheers
Chris.
PS. It is not related to a log file size over 2GB.
Posted: Tue Dec 13, 2005 1:43 pm
by wheelc
I should have added that restarting the SMTP Relay service starts things going again. (Until the next user tries SWA).
Let me know if you need any information and I will provide it.
Thanks.
Posted: Tue Dec 13, 2005 2:28 pm
by ScalixSupport
You can enable some debug logging in the SMTP Relay that will show the SMTP conversation.
Add the following line to /var/opt/scalix/sys/smtpd.cfg
and restart the relay
This will write the data to /var/opt/scalix/tmp/smtpd.log. Try sending a message again and then take a copy of the log file that is generated.
Turn off the debugging once you have finished as this can cause a number of problems if the log file grows over 2Gb.
If you can post the log file (edit it for security if required ) then we can see what's going on.
Cheers
Dave
Posted: Tue Dec 13, 2005 5:48 pm
by wheelc
Hello, Please see output from smtpd.log below: Operating system is Fedora FC4.
SMTP Relay 9.4.2.4 started (19170): Tue, 13 Dec 2005 20:57:28 +0000 (GMT)
Accepted client 1 from (jess.homedns.org)
Cli 19170/1 sent : 220 jess.homedns.org ESMTP Scalix SMTP Relay 9.4.2.4; Tue, 13 Dec 2005 20:58:16 +0000 (GMT)
Cli 19170/1 rcvd: 'EHLO jess.homedns.org'
Cli 19170/1 sent : 250-jess.homedns.org Hello jess.homedns.org [192.168.50.51], pleased to meet you
250-AUTH GSSAPI CRAM-MD5 PLAIN LOGIN DIGEST-MD5
250-AUTH=LOGIN
250-DSN
250 8BITMIME
Cli 19170/1 rcvd: 'MAIL FROM:<Chris.Wheeler@tnwsc.com>'
Cli 19170/1 sent : 250
Chris.Wheeler@tnwsc.com... Sender ok
Cli 19170/1 rcvd: 'RCPT TO:<wheelc@lineone.net> NOTIFY=FAILURE,DELAY'
SMTP Relay 9.4.2.4 finished (19170): Tue, 13 Dec 2005 21:01:32 +0000 (GMT)
Posted: Wed Dec 14, 2005 6:09 am
by wheelc
Hello,
There was no fatal errors but omshowlog produced the following. I do not think there is anything conclusive here.
WARNING PC Monitor (Socket Monitor) 12.13.05 07:53:11
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING PC Monitor (Socket Monitor) 12.13.05 07:53:17
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING PC Monitor (Socket Monitor) 12.13.05 09:54:09
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING Remote Client (U/I Access ) 12.13.05 11:56:02
[OM 9616] LAN FT - PC<->Host protocol error
User Name: John Bellairs / pat, homedns/CN=John Bellairs
<- ft_SendResult
-> pc_recv_logical_block
-> sck_raw_read
<- sck_raw_read
-> sck_raw_read
<- sck_raw_read
<- pc_recv_logical_block
-> ft_SendBlock
-> pc_send_logical_block
-> sck_raw_write
<- sck_raw_write
-> sck_raw_write
<- sck_raw_write
<- pc_send_logical_block
<- ft_SendBlock
<- /build/9.4.2.4/src/bin/ualr/ualr_ft.c:1677[100,9616]
WARNING PC Monitor (Socket Monitor) 12.13.05 12:20:21
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING PC Monitor (Socket Monitor) 12.13.05 12:20:55
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING PC Monitor (Socket Monitor) 12.13.05 12:21:03
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING PC Monitor (Socket Monitor) 12.13.05 13:55:59
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING PC Monitor (Socket Monitor) 12.13.05 14:03:19
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING PC Monitor (Socket Monitor) 12.13.05 14:04:08
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING PC Monitor (Socket Monitor) 12.13.05 14:04:30
[OM 9797] Cannot read initial request: Connection reset by peer
WARNING Remote Client (U/I Access ) 12.13.05 14:14:34
[OM.UI 404] Error sending data on command pipe. Error = 104
User Name: Bradley Day / pat, homedns/CN=Bradley Day
WARNING Remote Client (U/I Access ) 12.13.05 14:14:34
[OM.UI 401] UAL command/reply pipe error.
User Name: Bradley Day / pat, homedns/CN=Bradley Day
<- ct_AddSyncChangeRec
<- ual_PutSyncAddCtner
-> ual_GetNextAction
<- ual_GetNextAction
<- ual_DoPutSyncAction
<- ual_PutFolderSync
<- ual_RecvReply
-> pc_sendmessage
-> pc_recv_logical_block
-> sck_raw_read
-> ualrSck_LogBuffer
<- sck_raw_read
<- pc_recv_logical_block
<- pc_sendmessage
-> ual_LogDCError
<- /build/9.4.2.4/src/bin/ualr/ualr_main.c:430[101,401]
WARNING Remote Client (U/I Access ) 12.13.05 15:29:44
[OM.UI 404] Error sending data on command pipe. Error = 104
User Name: Mike Caiger / pat, homedns/CN=Mike Caiger
WARNING Remote Client (U/I Access ) 12.13.05 15:29:44
[OM.UI 401] UAL command/reply pipe error.
User Name: Mike Caiger / pat, homedns/CN=Mike Caiger
-> tf_CloseFile
<- tf_CloseFile
-> ual_StopSyncFile
-> ual_SetAppendFTData
<- ual_SetAppendFTData
<- ual_StopSyncFile
<- ual_GetFolderSync
<- ual_RecvReply
-> pc_sendmessage
-> pc_send_logical_block
-> sck_raw_write
<- sck_raw_write
<- pc_send_logical_block
<- pc_sendmessage
-> ual_LogDCError
<- /build/9.4.2.4/src/bin/ualr/ualr_main.c:430[101,401]
WARNING Remote Client (U/I Access ) 12.13.05 16:34:26
[OM 9616] LAN FT - PC<->Host protocol error
User Name: John Bellairs / pat, homedns/CN=John Bellairs
<- pc_recv_logical_block
<- ft_AwaitBlock
-> ft_SendResult
-> pc_send_logical_block
-> sck_raw_write
<- sck_raw_write
<- pc_send_logical_block
<- ft_SendResult
-> ft_AwaitBlock
-> pc_recv_logical_block
-> sck_raw_read
-> ualrSck_LogBuffer
<- sck_raw_read
<- pc_recv_logical_block
<- ft_AwaitBlock
<- /build/9.4.2.4/src/bin/ualr/ualr_ft.c:1677[100,9616]
SERIOUS ERROR Administration(Install Servic) 12.13.05 16:50:05
[OM 10414] Warning. Reset incomplete. Process 23694 of
subsystem SMTP Relay will not die in response to a SIGTERM signal.
WARNING POP3 interface(POP3 Process ) 12.13.05 19:31:33
[SYS 110] Connection timed out
<- pop3_DisplayContent
-> pop3_BrowseBody
-> im_ItemRef2FName
<- im_ItemRef2FName
<- pop3_BrowseBody
-> pop3_DisplayContent
<- pop3_DisplayContent
<- pop3_topItem
-> pop3_readItem
-> pop3_BrowseMsg
-> im_ItemRef2FName
<- im_ItemRef2FName
<- pop3_BrowseMsg
-> pop3_DisplayContent
<- /build/9.4.2.4/src/lib/ombase/os/os_fwrite.c:47[1,110]
<- /build/9.4.2.4/src/bin/pop3t/pop3t_direct.c:1120[1,110]
WARNING POP3 interface(POP3 Process ) 12.14.05 06:45:02
[SYS 104] Connection reset by peer
-> ct_GetSyncDirName
<- ct_GetSyncDirName
<- ct_CheckSyncFName
-> ct_AddSyncChangeRec
<- ct_AddSyncChangeRec
<- ct_ModifyContentRec
<- pop3_MarkMsgRead
<- pop3_readItem
-> pop3_readItem
-> pop3_BrowseMsg
-> im_ItemRef2FName
<- im_ItemRef2FName
<- pop3_BrowseMsg
-> pop3_DisplayContent
<- /build/9.4.2.4/src/lib/ombase/os/os_fwrite.c:47[1,104]
<- /build/9.4.2.4/src/bin/pop3t/pop3t_direct.c:1120[1,104]
Posted: Wed Dec 14, 2005 6:27 am
by wheelc
Hello, I can not shut it down as it is supporting the company users. However I know when the entry that you have pointed out occured. I solved it by killing the process manually and restarting. Is there anything else you can suggest? If not I will have to do this at the weekend.
Posted: Wed Dec 14, 2005 6:48 am
by ScalixSupport
wheelc wrote:Hello, I can not shut it down as it is supporting the company users. However I know when the entry that you have pointed out occured. I solved it by killing the process manually and restarting. Is there anything else you can suggest? If not I will have to do this at the weekend.
I'd still like to see the output of ps -ef.
Also, when you do omoff -d0 smtpd does it shut down cleanly now? Can you omstat -a and check for
SMTP Relay Partially Abor 10:54:18
It appears Tomcat is somewhat involved here if other clients are able to send mail. Can you post your caa.log after you made the following change to
/etc/opt/scalix/caa/config/log4j.properties
log4j.rootLogger=DEBUG
log4j.logger.com.scalix.caa.util.CAALogger=DEBUG, file
then restart Tomcat and try to send a message.
You are also mentioning FC4. Did you append anything to the Tomcat startup options`?
Cheers,
Sascha.
Posted: Wed Dec 14, 2005 7:22 am
by wheelc
Hello Info as requested:
[root@jess ~]# omstat -a
PC Monitor Started NON-STOP 0
Directory Relay Server Started 12.12.05
Notification Server Started 12.12.05 0
Shared memory daemon Started NON-STOP
Notification Monitor Started NON-STOP
Session Monitor Started NON-STOP
Container Access Monitor Started NON-STOP
Item Structure Server Stopped 12.11.05
Database Monitor Started 12.12.05
Licence Monitor Daemon Started NON-STOP
LDAP Daemon Started 12.12.05
Queue Manager Started NON-STOP
Item Delete Daemon Started NON-STOP
IMAP Server Daemon Started 12.12.05
SMTP Relay Started 12.13.05
Mime Browser Controller Started 12.12.05
NO PROBLEM THERE
2005-12-14 10:26:03,518 DEBUG [CAAConfigLoader.init:104] **** Start of Config Loader ****
2005-12-14 10:26:03,519 DEBUG [CAAConfigLoader.init:109] Framework config file: framework-config.xml
2005-12-14 10:26:03,521 DEBUG [CAAConfigLoader.loadConfigFile:150] Loading config from /etc/opt/scalix/caa/config/framework-config.xml
2005-12-14 10:26:03,624 DEBUG [CAAConfigLoader.parseConfigDocument:200] Service type: system
2005-12-14 10:26:03,626 DEBUG [CAAConfigLoader.getParamNodeValue:373] The node disabled was not found in service system, component null
2005-12-14 10:26:03,627 DEBUG [CAAConfigLoader.parseComponentNode:236] ComponentName: sessionManager
2005-12-14 10:26:03,629 DEBUG [CAAConfigLoader.parseComponentNode:251] Storing config for system, key sessionManager.class, value com.scalix.caa.framework.CAASessionManager
2005-12-14 10:26:03,647 DEBUG [CAASessionManager.readConfig:261] Reading config
2005-12-14 10:26:03,659 DEBUG [CAASessionManager.readConfig:295] Setting sessionTimeout=6000000
2005-12-14 10:26:03,661 DEBUG [CAASessionManager.readConfig:299] Setting cleanupFrequency=50000
2005-12-14 10:26:03,662 DEBUG [CAAConfigLoader.parseComponentNode:236] ComponentName: securityProvider
2005-12-14 10:26:03,663 DEBUG [CAAConfigLoader.parseComponentNode:251] Storing config for system, key securityProvider.class, value com.scalix.caa.security.CAAKerberosProvider
2005-12-14 10:26:03,671 DEBUG [CAAConfigLoader.getValue:56] Looking for config for system, key config.dir found /etc/opt/scalix/caa/config
2005-12-14 10:26:03,674 DEBUG [CAAKerberosProvider.readConfig:420] ParamName: loginFile, value krblogin.conf
2005-12-14 10:26:03,676 DEBUG [CAAConfigLoader.init:129] Service config file: scalix.res-config.xml
2005-12-14 10:26:03,677 DEBUG [CAAConfigLoader.loadConfigFile:150] Loading config from /etc/opt/scalix/caa/config/scalix.res-config.xml
2005-12-14 10:26:03,682 DEBUG [CAAConfigLoader.parseConfigDocument:200] Service type: scalix.res
2005-12-14 10:26:03,683 DEBUG [CAAConfigLoader.parseComponentNode:236] ComponentName: disabled
2005-12-14 10:26:03,684 DEBUG [CAAConfigLoader.getParamNodeValue:373] The node class was not found in service scalix.res, component disabled
2005-12-14 10:26:03,685 ERROR [CAAConfigLoader.parseComponentNode:244] Service scalix.res, Component disabled has no class defined!
2005-12-14 10:26:03,686 DEBUG [CAAConfigLoader.parseComponentNode:236] ComponentName: initializer
2005-12-14 10:26:03,687 DEBUG [CAAConfigLoader.parseComponentNode:251] Storing config for scalix.res, key initializer.class, value com.scalix.sac.ubermgr.caa.RESInitializer
2005-12-14 10:26:03,693 DEBUG [CAAConfigLoader.parseComponentParam:346] ParamName: class
2005-12-14 10:26:03,694 DEBUG [CAAConfigLoader.parseComponentParam:350] Storing config for scalix.res, key initializer.class, value
com.scalix.sac.ubermgr.caa.RESInitializer
2005-12-14 10:26:03,696 DEBUG [CAAConfigLoader.parseComponentNode:236] ComponentName: transformer
2005-12-14 10:26:03,697 DEBUG [CAAConfigLoader.parseComponentNode:251] Storing config for scalix.res, key transformer.class, value com.scalix.sac.ubermgr.caa.RESTransformer
2005-12-14 10:26:03,728 DEBUG [CAAConfigLoader.parseComponentParam:346] ParamName: class
2005-12-14 10:26:03,730 DEBUG [CAAConfigLoader.parseComponentParam:350] Storing config for scalix.res, key transformer.class, value
com.scalix.sac.ubermgr.caa.RESTransformer
2005-12-14 10:26:03,731 DEBUG [CAAConfigLoader.parseComponentNode:236] ComponentName: connection
2005-12-14 10:26:03,745 DEBUG [CAAConfigLoader.parseComponentNode:251] Storing config for scalix.res, key connection.class, value com.scalix.sac.ubermgr.caa.RESConnection
2005-12-14 10:26:03,751 DEBUG [CAAConfigLoader.parseComponentParam:346] ParamName: class
2005-12-14 10:26:03,752 DEBUG [CAAConfigLoader.parseComponentParam:350] Storing config for scalix.res, key connection.class, value
com.scalix.sac.ubermgr.caa.RESConnection
2005-12-14 10:26:03,753 DEBUG [CAAConfigLoader.parseComponentParam:346] ParamName: mode
2005-12-14 10:26:03,754 DEBUG [CAAConfigLoader.parseComponentParam:350] Storing config for scalix.res, key connection.mode, value 1
2005-12-14 10:26:03,759 DEBUG [CAAConfigLoader.parseComponentNode:295] Storing config for scalix.res, key connection.configurator.class, value com.scalix.caa.framework.CAAConnectionPoolManager
2005-12-14 10:26:03,762 DEBUG [CAAConnectionPoolManager.readConfig:350] ParamName: minConnections
2005-12-14 10:26:03,764 DEBUG [CAAConnectionPoolManager.readConfig:357] Value: 2
2005-12-14 10:26:03,766 DEBUG [CAAConnectionPoolManager.readConfig:350] ParamName: maxConnections
2005-12-14 10:26:03,767 DEBUG [CAAConnectionPoolManager.readConfig:357] Value: 8
2005-12-14 10:26:03,768 DEBUG [CAAConnectionPoolManager.readConfig:350] ParamName: maxLifeTime
2005-12-14 10:26:03,769 DEBUG [CAAConnectionPoolManager.readConfig:357] Value: 86400000
2005-12-14 10:26:03,770 DEBUG [CAAConnectionPoolManager.readConfig:350] ParamName: maxIdleTime
2005-12-14 10:26:03,771 DEBUG [CAAConnectionPoolManager.readConfig:357] Value: 300000
2005-12-14 10:26:03,772 DEBUG [CAAConnectionPoolManager.initializePool:249] Initializing pool for scalix.res with initial size of 2
2005-12-14 10:26:03,775 DEBUG [CAAConfigLoader.getValue:56] Looking for config for scalix.res, key connection.class found com.scalix.sac.ubermgr.caa.RESConnection
2005-12-14 10:26:03,776 DEBUG [CAAConnectionFactory.createConnection:49] Class name is com.scalix.sac.ubermgr.caa.RESConnection
2005-12-14 10:26:03,777 DEBUG [CAAConnectionPoolManager.createNewAndAddToPool:285] Adding new connection to pool for scalix.res and endpoint null
2005-12-14 10:26:03,793 DEBUG [CAAConnectionPoolManager.logConnectionPool:315] Connection pool scalix.res status: min=2,max=10,size=1,used=0
2005-12-14 10:26:03,795 DEBUG [CAAConfigLoader.getValue:56] Looking for config for scalix.res, key connection.class found com.scalix.sac.ubermgr.caa.RESConnection
2005-12-14 10:26:03,796 DEBUG [CAAConnectionFactory.createConnection:49] Class name is com.scalix.sac.ubermgr.caa.RESConnection
2005-12-14 10:26:03,799 DEBUG [CAAConnectionPoolManager.createNewAndAddToPool:285] Adding new connection to pool for scalix.res and endpoint null
2005-12-14 10:26:03,800 DEBUG [CAAConnectionPoolManager.logConnectionPool:315] Connection pool scalix.res status: min=2,max=10,size=2,used=0
2005-12-14 10:26:03,801 DEBUG [CAAConfigLoader.parseComponentNode:236] ComponentName: service
2005-12-14 10:26:03,801 DEBUG [CAAConfigLoader.parseComponentNode:251] Storing config for scalix.res, key service.class, value com.scalix.sac.ubermgr.caa.RESService
2005-12-14 10:26:03,806 DEBUG [CAAConfigLoader.parseComponentParam:346] ParamName: class
2005-12-14 10:26:03,807 DEBUG [CAAConfigLoader.parseComponentParam:350] Storing config for scalix.res, key service.class, value
com.scalix.sac.ubermgr.caa.RESService
2005-12-14 10:26:03,868 DEBUG [CAAConfigLoader.init:129] Service config file: sample-service-config.xml
2005-12-14 10:26:03,869 DEBUG [CAAConfigLoader.loadConfigFile:150] Loading config from /etc/opt/scalix/caa/config/sample-service-config.xml
2005-12-14 10:26:03,874 WARN [CAAConfigLoader.parseConfigDocument:224] No services are configured in this config file
2005-12-14 10:26:03,875 DEBUG [CAAConfigLoader.init:145] **** End of Config Loader ****
2005-12-14 10:26:03,889 DEBUG [CAAInitializerManager.loadAllInitializers:27] **** Start of Load Initializers ****
2005-12-14 10:26:03,891 DEBUG [CAAConfigLoader.getValue:56] Looking for config for system, key initializer.class found null
2005-12-14 10:26:03,892 DEBUG [CAAConfigLoader.getValue:56] Looking for config for scalix.res, key initializer.class found com.scalix.sac.ubermgr.caa.RESInitializer
2005-12-14 10:26:03,893 DEBUG [CAAInitializerFactory.getInitializer:42] Class name for scalix.res is com.scalix.sac.ubermgr.caa.RESInitializer
2005-12-14 10:26:03,894 DEBUG [CAAInitializerFactory.getInitializer:63] Initializer for scalix.res is com.scalix.sac.ubermgr.caa.RESInitializer@3a5794
2005-12-14 10:26:03,895 DEBUG [CAAInitializerManager.loadAllInitializers:49] Initializing service scalix.res
2005-12-14 10:26:03,902 DEBUG [UberMgrConfig.loadFile:171] Loading Ubermanager properties...
2005-12-14 10:26:03,923 DEBUG [UberMgrConfig.loadFile:175] Finished Loading Ubermanager properties
2005-12-14 10:26:03,924 DEBUG [UberMgrConfig.loadLdapAttribs:187] Loading Ldap Attribute mappings...
2005-12-14 10:26:03,927 DEBUG [UberMgrConfig.loadLdapAttribs:191] Finished Loading Ldap Attribute mappings...entries read=33
2005-12-14 10:26:03,940 DEBUG [UberMgrConfig.loadDirectoryAttribs:203] Loading X.400 Attributes for USERLIST
2005-12-14 10:26:03,943 DEBUG [UberMgrConfig.loadDirectoryAttribs:221] Finised Loading X.400 Attributes for USERLIST
2005-12-14 10:26:03,943 DEBUG [UberMgrConfig.loadDirectoryAttribs:203] Loading X.400 Attributes for SYSTEM
2005-12-14 10:26:03,945 DEBUG [UberMgrConfig.loadDirectoryAttribs:221] Finised Loading X.400 Attributes for SYSTEM
2005-12-14 10:26:03,946 DEBUG [RESInitializer.initNotificationTables:145] Reading Event Notifications Table:events.data
2005-12-14 10:26:03,973 DEBUG [EventTable.readTable:37] com.scalix.sac.ubermgr.events.EventTable:Reading persistent data from /etc/opt/scalix/caa/scalix.res/config/store/events.data
2005-12-14 10:26:03,974 DEBUG [EventTable.readTable:51] com.scalix.sac.ubermgr.events.EventTable:No events persitence data found
2005-12-14 10:26:03,979 DEBUG [RESInitializer.initNotificationTables:147] Finished Event Notifications Table
2005-12-14 10:26:03,993 INFO [GuidToServerCache$CleanupThread.run:39] Guid2Server cache is empty. Skipping cleanup
2005-12-14 10:26:03,994 INFO [NotificationEventListener.launch:243] Main Notification Event Listener thread launched...
2005-12-14 10:26:03,996 INFO [NotificationEventListener.launch:246] Notification Worker thread com.scalix.sac.ubermgr.events.NotificationEventListener$WorkerThread-thread-0 launched...
2005-12-14 10:26:03,997 INFO [NotificationEventListener.launch:246] Notification Worker thread com.scalix.sac.ubermgr.events.NotificationEventListener$WorkerThread-thread-1 launched...
2005-12-14 10:26:04,001 DEBUG [RESMonitor.<init>:43] Now monitoring RES servers. We will check every 60 seconds and tolerate no heartbeat for 720 seconds
2005-12-14 10:26:04,003 INFO [RESInitializer.initNotificationListener:201] RESMonitor-thread Thread launched...
2005-12-14 10:26:04,005 DEBUG [RESInitializer.initLocalDeployment:89] Registering server jess.homedns.org in local mode
2005-12-14 10:26:04,008 DEBUG [UberMgrConfig.loadServiceDaemonMappings:71] Loading Service/Daemon Mappings
2005-12-14 10:26:04,024 DEBUG [UberMgrConfig.loadServiceDaemonMappings:74] Finished Loading Service/Daemon Mappings
2005-12-14 10:26:04,025 DEBUG [UberMgrConfig.loadServiceDaemonMappings:75] Service/Daemon Mappings=36
2005-12-14 10:26:04,026 DEBUG [UberMgrConfig.loadScalixQueuesNames:58] Loading Service Scalix Queue Names
2005-12-14 10:26:04,028 DEBUG [UberMgrConfig.loadScalixQueuesNames:61] Finished Loading Scalix Queue Names
2005-12-14 10:26:04,029 DEBUG [UberMgrConfig.loadScalixCompsRpmNames:50] Loading Scalix Component RPM prefix names
2005-12-14 10:26:04,030 DEBUG [UberMgrConfig.loadScalixCompsRpmNames:53] Finished Loading Scalix Component RPM prefix names
2005-12-14 10:26:04,032 DEBUG [CAAInitializerManager.loadAllInitializers:67] **** End of Load Initializers ****
2005-12-14 10:26:04,032 INFO [SOAPDispatcherServlet.init:118] ====> CAA started, you may fire when ready <====
2005-12-14 10:26:04,058 DEBUG [RESMonitor.run:64] There are no remote servers and 1 local server registered
2005-12-14 10:26:04,071 DEBUG [RESMonitor.run:84] Skipping local server jess.homedns.org
2005-12-14 10:27:04,043 DEBUG [RESMonitor.run:64] There are no remote servers and 1 local server registered
2005-12-14 10:27:04,044 DEBUG [RESMonitor.run:84] Skipping local server jess.homedns.org
2005-12-14 10:28:04,015 DEBUG [RESMonitor.run:64] There are no remote servers and 1 local server registered
2005-12-14 10:28:04,016 DEBUG [RESMonitor.run:84] Skipping local server jess.homedns.org
2005-12-14 10:29:03,990 DEBUG [RESMonitor.run:64] There are no remote servers and 1 local server registered
2005-12-14 10:29:03,991 DEBUG [RESMonitor.run:84] Skipping local server jess.homedns.org
2005-12-14 10:30:03,962 DEBUG [RESMonitor.run:64] There are no remote servers and 1 local server registered
2005-12-14 10:30:03,963 DEBUG [RESMonitor.run:84] Skipping local server jess.homedns.org
2005-12-14 10:31:03,935 DEBUG [RESMonitor.run:64] There are no remote servers and 1 local server registered
2005-12-14 10:31:03,936 DEBUG [RESMonitor.run:84] Skipping local server jess.homedns.org
OK?
I have added info to the start i.e. JAVA_OPTS
/usr/java/j2sdk1.4.2_10/bin/java -Djava.net.preferIPv4Stack=true -server -Xms256m -Xmx256m -Djava.endorsed.dirs=/usr/jakarta/jakarta-tomcat-5.0.28/common/endorsed -classpath /usr/java/j2sdk1.4.2_10/lib/tools.jar:/usr/jakarta/jakarta-tomcat-5.0.28/bin/bootstrap.jar:/usr/jakarta/jakarta-tomcat-5.0.28/bin/commons-logging-api.jar -Dcatalina.base=/usr/jakarta/jakarta-tomcat-5.0.28 -Dcatalina.home=/usr/jakarta/jakarta-tomcat-5.0.28 -Djava.io.tmpdir=/usr/jakarta/jakarta-tomcat-5.0.28/temp org.apache.catalina.startup.Bootstrap start
cheers
Chris.
Posted: Wed Dec 14, 2005 7:29 am
by wheelc
I thought this might help also from the scalix-swa_log:
2005-12-14 10:31:14 StandardContext[/webmail]ip: 212.183.131.161; username: chris.wheeler; message: <SOAP-ENV:Fault><faultcode>SOAP-ENV:SERVER.MessagingException</faultcode><faultstring>methodName = send
</faultstring><detail><e:MessagingException xmlns:e="http://scalix.com/errors"><message>methodName = send
</message><debug>javax.mail.MessagingException: [EOF]
at com.sun.mail.smtp.SMTPTransport.issueCommand(SMTPTransport.java:1020)
at com.sun.mail.smtp.SMTPTransport.rcptTo(SMTPTransport.java:824)
at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:389)
at com.oddpost.server.module.SoapMail.sendMessage(SoapMail.java:1708)
at com.oddpost.server.module.SoapMail.send(SoapMail.java:870)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at com.oddpost.soap.SoapModule.invokeMethod(SoapModule.java:238)
at com.oddpost.soap.SoapRequestImpl.execute(SoapRequestImpl.java:140)
at com.oddpost.server.HttpRequestHandler.handleRequest(HttpRequestHandler.java:221)
at com.oddpost.server.SoapServlet.doPost(SoapServlet.java:50)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at com.oddpost.server.filter.HttpConfFilter.doFilter(HttpConfFilter.java:175)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
... skipping the last 25 lines as irrelevant...
</debug></e:MessagingException></detail></SOAP-ENV:Fault>
cheers
Chris
Posted: Wed Dec 14, 2005 8:05 am
by ScalixSupport
wheelc wrote:I thought this might help also from the scalix-swa_log:
2005-12-14 10:31:14 StandardContext[/webmail]ip: 212.183.131.161; username: chris.wheeler; message: <SOAP-ENV:Fault><faultcode>SOAP-ENV:SERVER.MessagingException</faultcode><faultstring>methodName = send
</faultstring><detail><e:MessagingException xmlns:e="http://scalix.com/errors"><message>methodName = send
</message><debug>javax.mail.MessagingException: [EOF]
at com.sun.mail.smtp.SMTPTransport.issueCommand(SMTPTransport.java:1020)
at com.sun.mail.smtp.SMTPTransport.rcptTo(SMTPTransport.java:824)
at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:389)
at com.oddpost.server.module.SoapMail.sendMessage(SoapMail.java:1708)
at com.oddpost.server.module.SoapMail.send(SoapMail.java:870)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at com.oddpost.soap.SoapModule.invokeMethod(SoapModule.java:238)
at com.oddpost.soap.SoapRequestImpl.execute(SoapRequestImpl.java:140)
at com.oddpost.server.HttpRequestHandler.handleRequest(HttpRequestHandler.java:221)
at com.oddpost.server.SoapServlet.doPost(SoapServlet.java:50)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at com.oddpost.server.filter.HttpConfFilter.doFilter(HttpConfFilter.java:175)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
... skipping the last 25 lines as irrelevant...
</debug></e:MessagingException></detail></SOAP-ENV:Fault>
cheers
Chris
OK, we're on to something here. The error message indicates that it choked on the RCPT TO command, which makes me wonder what ACCEPT lines you have in your smtpd.cfg. This should in theory not make any difference to SWA crashing, but ... Can you show your smtpd.cfg, please?
Also, can you allocate 512MB memory to the java options instead of 256, that seems a little low.
You need to restart Tomcat after making the change.
Cheers,
Sascha.
Posted: Wed Dec 14, 2005 11:02 am
by wheelc
Config info below:
RELAY accept localhost
RELAY accept .homedns.org
RELAY Log_Reject ALL
# extra rules added to prevent open relay usage
RECIPIENT Log_Reject *@*@*
RECIPIENT Log_Reject *%*
RECIPIENT Log_Reject *!*
RECIPIENT Log_Reject *#*@*
#DEBUG_LOG=TRUE
Have tuned tomcat to 512 also
Posted: Wed Dec 14, 2005 11:18 am
by wheelc
OK, setting the tomcat JAVA_OPT to 512 seems to have done the trick! Will keep you posted. Thanks for the help.