[
https://issues.apache.org/jira/browse/JAMES-1418?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13395796#comment-13395796
]
Chet Wang commented on JAMES-1418:
----------------------------------
Hi Eric/Serkant,
I have to comment again, and apologize for my insufficient testing. I said
'James smtp authentication is always working' after I only updated mailet
'RemoteAddrNotInNetwork' in mailetcontainer.conf, and smtpserver.conf is still
with authRequired=false.
Now I install thunderbird client and have a deeper test/comparison. I'm sure
there indeed is issue on smtp authentication.
Here is my scenario:
1. set authRequired=false and verifyIdentity=true/announce, Thunderbird with
wrong user account setting.
Result: Thunderbird can send mail to recipient, so does my test code.
2. set authRequired=true and verifyIdentity=true/announce, Thunderbird with
wrong user account setting.
Result: Thunderbird can NOT send mail to recipient, but my test code still
be able to send mails.
I found something intresting in smtpserver.log when setting log level to DEBUG:
if using thunderbird, it shows like below:
INFO 09:50:54,958 | james.smtpserver | Id='1183361305' User='' Connection
established from 115.205.3.5
DEBUG 09:50:55,700 | james.smtpserver | Id='1183361305' User=''
org.apache.james.protocols.api.handler.CommandDispatcher received: EHLO
DEBUG 09:50:55,700 | james.smtpserver | Id='1183361305' User='' Lookup command
handler for command: EHLO
DEBUG 09:50:55,701 | james.smtpserver | Id='1183361305' User=''
org.apache.james.protocols.smtp.core.esmtp.EhloCmdHandler:
[250-ip-10-146-22-253 Hello [192.1
68.1.125] [115.205.3.5]), 250-AUTH LOGIN PLAIN, 250-AUTH=LOGIN PLAIN,
250-PIPELINING, 250-ENHANCEDSTATUSCODES, 250 8BITMIME]
DEBUG 09:51:45,986 | james.smtpserver | Id='1183361305' User=''
org.apache.james.protocols.api.handler.CommandDispatcher received: AUTH
DEBUG 09:51:45,987 | james.smtpserver | Id='1183361305' User='' Lookup command
handler for command: AUTH
DEBUG 09:51:45,993 | james.smtpserver | Id='1183361305' User='' executing hook
org.apache.james.smtpserver.UsersRepositoryAuthHook@763c69f
DEBUG 09:51:46,051 | james.smtpserver | Id='1183361305' User='test' AUTH method
PLAIN succeeded
DEBUG 09:51:46,051 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.protocols.smtp.core.esmtp.AuthCmdHandler: [235 Authentication
Successful
]
DEBUG 09:51:46,815 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.protocols.api.handler.CommandDispatcher received: MAIL
DEBUG 09:51:46,816 | james.smtpserver | Id='1183361305' User='test' Lookup
command handler for command: MAIL
DEBUG 09:51:46,816 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.smtpserver.JamesMailCmdHandler: [250 2.1.0 Sender
<[email protected]>
OK]
DEBUG 09:51:47,635 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.protocols.api.handler.CommandDispatcher received: RCPT
DEBUG 09:51:47,636 | james.smtpserver | Id='1183361305' User='test' Lookup
command handler for command: RCPT
DEBUG 09:51:47,637 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.smtpserver.fastfail.ValidRcptHandler
DEBUG 09:51:47,641 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.protocols.smtp.core.log.HookResultLogger@4a09ff12
DEBUG 09:51:47,642 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.smtpserver.fastfail.ValidRcptHandler: result=8 (DECLINED)
DEBUG 09:51:47,642 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@56491cb7
DEBUG 09:51:47,643 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.smtpserver.AuthRequiredToRelayRcptHook
DEBUG 09:51:47,643 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.protocols.smtp.core.log.HookResultLogger@4a09ff12
DEBUG 09:51:47,644 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.smtpserver.AuthRequiredToRelayRcptHook: result=8 (DECLINED)
DEBUG 09:51:47,644 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@56491cb7
DEBUG 09:51:47,644 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook
DEBUG 09:51:47,647 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.protocols.smtp.core.log.HookResultLogger@4a09ff12
INFO 09:51:47,648 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook: result=2
(DENY)
DEBUG 09:51:47,649 | james.smtpserver | Id='1183361305' User='test' executing
hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@56491cb7
DEBUG 09:51:47,650 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.smtpserver.JamesRcptCmdHandler: [503 5.7.1 Incorrect
Authentication for
Specified Email Address]
DEBUG 09:52:11,691 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.protocols.api.handler.CommandDispatcher received: QUIT
DEBUG 09:52:11,692 | james.smtpserver | Id='1183361305' User='test' Lookup
command handler for command: QUIT
DEBUG 09:52:11,692 | james.smtpserver | Id='1183361305' User='test'
org.apache.james.protocols.smtp.core.QuitCmdHandler: [221 2.0.0
ip-10-146-22-253 Service closing transmission channel]
INFO 09:52:11,694 | james.smtpserver | Id='1183361305' User='test' Connection
closed for 115.205.3.5
Please note, User info is correct, it is 'test'.
But, if using my test code, it shows like:
INFO 10:11:12,611 | james.smtpserver | Id='2017842455' User='' Connection
established from 115.236.189.178
DEBUG 10:11:13,244 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.api.handler.CommandDispatcher received: EHLO
DEBUG 10:11:13,245 | james.smtpserver | Id='2017842455' User='' Lookup command
handler for command: EHLO
DEBUG 10:11:13,246 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.smtp.core.esmtp.EhloCmdHandler:
[250-ip-10-146-22-253 Hello HGHLTR
8Y32DM.corp.capgemini.com [115.236.189.178]), 250-PIPELINING,
250-ENHANCEDSTATUSCODES, 250 8BITMIME]
DEBUG 10:11:13,885 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.api.handler.CommandDispatcher received: MAIL
DEBUG 10:11:13,886 | james.smtpserver | Id='2017842455' User='' Lookup command
handler for command: MAIL
DEBUG 10:11:13,887 | james.smtpserver | Id='2017842455' User=''
org.apache.james.smtpserver.JamesMailCmdHandler: [250 2.1.0 Sender
<[email protected]>
OK]
DEBUG 10:11:14,514 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.api.handler.CommandDispatcher received: RCPT
DEBUG 10:11:14,515 | james.smtpserver | Id='2017842455' User='' Lookup command
handler for command: RCPT
DEBUG 10:11:14,515 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.fastfail.ValidRcptHandler
DEBUG 10:11:14,521 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.protocols.smtp.core.log.HookResultLogger@2a15c952
DEBUG 10:11:14,521 | james.smtpserver | Id='2017842455' User=''
org.apache.james.smtpserver.fastfail.ValidRcptHandler: result=8 (DECLINED)
DEBUG 10:11:14,522 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.jmx.HookResultJMXMonitor@7c543c13
DEBUG 10:11:14,522 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.AuthRequiredToRelayRcptHook
DEBUG 10:11:14,523 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.protocols.smtp.core.log.HookResultLogger@2a15c952
DEBUG 10:11:14,523 | james.smtpserver | Id='2017842455' User=''
org.apache.james.smtpserver.AuthRequiredToRelayRcptHook: result=8 (DECLINED)
DEBUG 10:11:14,524 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.jmx.HookResultJMXMonitor@7c543c13
DEBUG 10:11:14,524 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook
DEBUG 10:11:14,524 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.protocols.smtp.core.log.HookResultLogger@2a15c952
DEBUG 10:11:14,525 | james.smtpserver | Id='2017842455' User=''
org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook: result=8
(DECLINED)
DEBUG 10:11:14,525 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.jmx.HookResultJMXMonitor@7c543c13
DEBUG 10:11:14,525 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.protocols.smtp.core.PostmasterAbuseRcptHook
DEBUG 10:11:14,526 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.protocols.smtp.core.log.HookResultLogger@2a15c952
DEBUG 10:11:14,526 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.smtp.core.PostmasterAbuseRcptHook: result=8
(DECLINED)
DEBUG 10:11:14,526 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.jmx.HookResultJMXMonitor@7c543c13
DEBUG 10:11:14,527 | james.smtpserver | Id='2017842455' User=''
org.apache.james.smtpserver.JamesRcptCmdHandler: [250 2.1.5 Recipient
<[email protected]> OK]
DEBUG 10:11:15,315 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.api.handler.CommandDispatcher received: DATA
DEBUG 10:11:15,316 | james.smtpserver | Id='2017842455' User='' Lookup command
handler for command: DATA
DEBUG 10:11:15,317 | james.smtpserver | Id='2017842455' User=''
org.apache.james.smtpserver.JamesDataCmdHandler: [354 Ok Send data ending with
<CRLF>.<CRLF>]
DEBUG 10:11:16,599 | james.smtpserver | Id='2017842455' User='' executing james
message handler
org.apache.james.protocols.smtp.core.esmtp.MailSizeEsmtpExtension@3cccc8bd
DEBUG 10:11:16,600 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.protocols.smtp.core.log.HookResultLogger@2a15c952
DEBUG 10:11:16,600 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.smtp.core.esmtp.MailSizeEsmtpExtension: result=8
(DECLINED)
DEBUG 10:11:16,601 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.jmx.HookResultJMXMonitor@7c543c13
DEBUG 10:11:16,601 | james.smtpserver | Id='2017842455' User='' executing james
message handler
org.apache.james.smtpserver.AddDefaultAttributesMessageHook@29a39fe5
DEBUG 10:11:16,602 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.protocols.smtp.core.log.HookResultLogger@2a15c952
DEBUG 10:11:16,602 | james.smtpserver | Id='2017842455' User=''
org.apache.james.smtpserver.AddDefaultAttributesMessageHook: result=8 (DECLINED)
DEBUG 10:11:16,603 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.jmx.HookResultJMXMonitor@7c543c13
DEBUG 10:11:16,603 | james.smtpserver | Id='2017842455' User='' executing james
message handler org.apache.james.smtpserver.SendMailHandler@355688be
DEBUG 10:11:16,603 | james.smtpserver | Id='2017842455' User='' sending mail
INFO 10:11:16,607 | james.smtpserver | Id='2017842455' User='' Successfully
spooled mail Mail1340014276599-7dae1b6d-6e71-42ef-a9d7-bf74c7a67590 from
[email protected] on 115.236.189.178/115.236.189.178 for
[[email protected]]
DEBUG 10:11:16,607 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.protocols.smtp.core.log.HookResultLogger@2a15c952
DEBUG 10:11:16,607 | james.smtpserver | Id='2017842455' User=''
org.apache.james.smtpserver.SendMailHandler: result=1 (OK)
DEBUG 10:11:16,608 | james.smtpserver | Id='2017842455' User='' executing hook
org.apache.james.smtpserver.jmx.HookResultJMXMonitor@7c543c13
DEBUG 10:11:17,397 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.api.handler.CommandDispatcher received: QUIT
DEBUG 10:11:17,405 | james.smtpserver | Id='2017842455' User='' Lookup command
handler for command: QUIT
DEBUG 10:11:17,405 | james.smtpserver | Id='2017842455' User=''
org.apache.james.protocols.smtp.core.QuitCmdHandler: [221 2.0.0
ip-10-146-22-253 Service closing transmission channel]
INFO 10:11:17,407 | james.smtpserver | Id='2017842455' User='' Connection
closed for 115.236.189.178
These logs indicate some differences, especially in user field logging.
@Eric, could you take a look at it when you have time?
> SMTP authentication verifyIdentity is passed off
> ------------------------------------------------
>
> Key: JAMES-1418
> URL: https://issues.apache.org/jira/browse/JAMES-1418
> Project: JAMES Server
> Issue Type: Bug
> Components: SMTPServer
> Affects Versions: 3.0-beta3, 3.0-beta4
> Reporter: Serkant Uluderya
> Priority: Critical
> Labels: smtp
> Attachments: MailSender.java, james.out, smtpserver.conf
>
> Original Estimate: 24h
> Remaining Estimate: 24h
>
> I've been trying to enable SMTP authentication on apache-james-3.0-beta4 but
> I can't manage it. I made the log level as DEBUG for SMTP service. It seems
> that although the identity verification fails, the user is enable to post a
> mail.
> In smtpserver.conf file I made the following changes, it is attached also.
> <authRequired>announce</authRequired>
> <!--<authorizedAddresses>127.0.0.0/8</authorizedAddresses>-->
> <verifyIdentity>true</verifyIdentity>
> Here is the log parts that I suspected.
> INFO 17:53:08,746 | james.smtpserver | This SMTP server requires
> authentication.
> ......
> DEBUG 18:03:33,798 | james.smtpserver | Id='9403936' User=''
> org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook: result=8
> (DECLINED)
> DEBUG 18:03:33,799 | james.smtpserver | Id='9403936' User='' executing hook
> org.apache.james.smtpserver.jmx.HookResultJMXMonitor@1eee3fb
> DEBUG 18:03:33,799 | james.smtpserver | Id='9403936' User='' executing hook
> org.apache.james.protocols.smtp.core.PostmasterAbuseRcptHook
> DEBUG 18:03:33,799 | james.smtpserver | Id='9403936' User='' executing hook
> org.apache.james.protocols.smtp.core.log.HookResultLogger@10a3ffc
> DEBUG 18:03:33,799 | james.smtpserver | Id='9403936' User=''
> org.apache.james.protocols.smtp.core.PostmasterAbuseRcptHook: result=8
> (DECLINED)
> DEBUG 18:03:33,799 | james.smtpserver | Id='9403936' User='' executing hook
> org.apache.james.smtpserver.jmx.HookResultJMXMonitor@1eee3fb
> DEBUG 18:03:33,800 | james.smtpserver | Id='9403936' User=''
> org.apache.james.smtpserver.JamesRcptCmdHandler: [250 2.1.5 Recipient
> <[email protected]> OK]
> DEBUG 18:03:33,815 | james.smtpserver | Id='9403936' User=''
> org.apache.james.protocols.api.handler.CommandDispatcher received: DATA
> DEBUG 18:03:33,815 | james.smtpserver | Id='9403936' User='' Lookup command
> handler for command: DATA
> DEBUG 18:03:33,826 | james.smtpserver | Id='9403936' User=''
> org.apache.james.smtpserver.JamesDataCmdHandler: [354 Ok Send data ending
> with <CRLF>.<CRLF>]
> DEBUG 18:03:33,870 | james.smtpserver | Id='9403936' User='' executing james
> message handler
> org.apache.james.protocols.smtp.core.esmtp.MailSizeEsmtpExtension@4a1908
> DEBUG 18:03:33,872 | james.smtpserver | Id='9403936' User='' executing hook
> org.apache.james.protocols.smtp.core.log.HookResultLogger@10a3ffc
> DEBUG 18:03:33,872 | james.smtpserver | Id='9403936' User=''
> org.apache.james.protocols.smtp.core.esmtp.MailSizeEsmtpExtension: result=8
> (DECLINED)
> DEBUG 18:03:33,874 | james.smtpserver | Id='9403936' User='' executing hook
> org.apache.james.smtpserver.jmx.HookResultJMXMonitor@1eee3fb
> DEBUG 18:03:33,874 | james.smtpserver | Id='9403936' User='' executing james
> message handler
> org.apache.james.smtpserver.AddDefaultAttributesMessageHook@1cfb84c
> DEBUG 18:03:33,875 | james.smtpserver | Id='9403936' User='' executing hook
> org.apache.james.protocols.smtp.core.log.HookResultLogger@10a3ffc
> DEBUG 18:03:33,875 | james.smtpserver | Id='9403936' User=''
> org.apache.james.smtpserver.AddDefaultAttributesMessageHook: result=8
> (DECLINED)
> DEBUG 18:03:33,875 | james.smtpserver | Id='9403936' User='' executing hook
> org.apache.james.smtpserver.jmx.HookResultJMXMonitor@1eee3fb
> DEBUG 18:03:33,875 | james.smtpserver | Id='9403936' User='' executing james
> message handler org.apache.james.smtpserver.SendMailHandler@4cb3a4
> DEBUG 18:03:33,876 | james.smtpserver | Id='9403936' User='' sending mail
> INFO 18:03:33,906 | james.smtpserver | Id='9403936' User='' Successfully
> spooled mail Mail1339427013851-53bd7bc6-0c36-417f-acee-8af76691b35e from
> [email protected] on 192.168.200.90/192.168.200.90 for
> [[email protected]]
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
