james-server-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Chet Wang (JIRA)" <server-...@james.apache.org>
Subject [jira] [Commented] (JAMES-1418) SMTP authentication verifyIdentity is passed off
Date Mon, 18 Jun 2012 10:27:43 GMT

    [ 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 <test@virbraligo.org>
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 <diggywang@virbraligo.org>
 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 <chetwang@capgemini.com> 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 diggywang@virbraligo.org on 115.236.189.178/115.236.189.178
for [chetwang@capgemini.com]
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 <receiver@mail.test.com> 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 sender@mail.test.com on 192.168.200.90/192.168.200.90
for [receiver@mail.test.com]

--
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: server-dev-unsubscribe@james.apache.org
For additional commands, e-mail: server-dev-help@james.apache.org


Mime
View raw message