Re: Unable to send messages, relay denied. IMAP does work ok.

On Mon, Jul 10, 2023 at 1:26 PM Jean Helou <[email protected]> wrote:

> Hi marc,
>
> I took a look at the logs, I never encountered this issue so I'm not
> entirely sure what's going on but the failure seems to be in this part :
>
> > 2023-07-10 09:51:54,390 ERROR |
> > org.apache.james.domainlist.lib.AbstractDomainList | Cannot get IP
> > address(es) for Domain : localhost
> > 2023-07-10 09:51:54,394 WARN  |
> > org.apache.james.dnsservice.dnsjava.DNSJavaService | Error determining
> > result
> > java.lang.IllegalStateException: Lookup of localhost A isn't done
> >
> 2023-07-10 09:51:54,394 ERROR |
> > org.apache.james.domainlist.lib.AbstractDomainList | Cannot get IP
> > address(es) for Domain : localhost
> > 2023-07-10 09:51:54,394 INFO  |
> > org.apache.james.protocols.smtp.core.log.HookResultLogger |
> > org.apache.james.smtpserver.AuthRequiredToRelayRcptHook: result= (DENY
> > Connected)
> >
>
> If I interpret this correctly james is unable to figure out an IP address
> for localhost which is quite surprising...
> if you are running linux I suggest running either dig localhost or nslookup
> localhost and ping localhost to see if its a systemwide issue or something
> specific to james dns config.
>


Hi Jean - Again thanks for your help -  Below are the results from the
tests you suggested I make. It all seems OK to my eyes, but maybe you will
see a red flag....

quasar:/mail/apache-james/log # dig localhost

; <<>> DiG 9.16.6 <<>> localhost
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 11991
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
; COOKIE: ddc9c83e814a4f950100000064accef13af76be95f7cbc53 (good)
;; QUESTION SECTION:
;localhost.                     IN      A

;; ANSWER SECTION:
localhost.              604800  IN      A       127.0.0.1

;; Query time: 0 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Mon Jul 10 20:39:29 PDT 2023
;; MSG SIZE  rcvd: 82

quasar:/mail/apache-james/log # nslookup localhost
Server:         127.0.0.1
Address:        127.0.0.1#53

Name:   localhost.mydomainname.com
Address: 127.0.0.1

quasar:/mail/apache-james/log # ping localhost
PING localhost (127.0.0.1) 56(84) bytes of data.
64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.035 ms
64 bytes from localhost (127.0.0.1): icmp_seq=2 ttl=64 time=0.040 ms
64 bytes from localhost (127.0.0.1): icmp_seq=3 ttl=64 time=0.047 ms
^C
--- localhost ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2042ms
rtt min/avg/max/mdev = 0.035/0.040/0.047/0.008 ms

if you are running on macos, you might want to check your hostfile
> /etc/hosts which could be empty
>
> Not running on macos, but on the Linux distro - OpenSuSE Leap 15.4 x64. I
will include my /etc/hosts file here, just in case you see something I
don't, with some sensitive information obscured...

 #
# hosts         This file describes a number of hostname-to-address
#               mappings for the TCP/IP subsystem.  It is mostly
#               used at boot time, when no name servers are running.
#               On small systems, this file can be used instead of a
#               "named" name server.
# Syntax:
#
# IP-Address  Full-Qualified-Hostname  Short-Hostname
#

127.0.0.1 localhost
127.0.0.1 imap.localhost
127.0.0.1 smtp.localhost

# special IPv6 addresses
::1             localhost ipv6-localhost ipv6-loopback
::1             ipv6-localhost ipv6-loopback

fe00::0         ipv6-localnet

ff00::0         ipv6-mcastprefix
ff02::1         ipv6-allnodes
ff02::2         ipv6-allrouters
ff02::3         ipv6-allhosts
192.168.10.100 quasar.mydomain.com quasar
192.168.10.200 quasarIMZ.mydomain.com quasarIMZ
111.111.111.18 quasar

if none of this helps and the link to a dns issue doesn't help, you may
> want to enable debug logging for org.xbill.DNS which would give more
> insight into why the resolution of localhost fails
>

Uh, I don't grok what you are saying here Jean.  What link to a dns issue
are you referring to? And I don't know how to enable debug logging for
org.xbill.DNS. Google search implies it is some java library and that is as
far as I got. (Haven't done Java programming in quite a few years, decades
even!)

On another front, I searched through another James log file called
"wrapper.log" after attempting to send another email to an external
internet address. I found a different clue, but I don't really understand
it either. I will copy/paste the interesting lines from "wrapper.log", the
rest of the file just has a lot of normal stuff...

INFO   | jvm 1    | 2023/07/10 21:21:10 | 2023-07-10 21:21:10,355 INFO  |
org.apache.james.protocols.netty.BasicChannelUpstreamHandler | Connection
established from 192.168.10.10
INFO   | jvm 1    | 2023/07/10 21:21:10 | 2023-07-10 21:21:10,574 INFO  |
org.apache.james.protocols.smtp.core.log.HookResultLogger |
org.apache.james.smtpserver.AuthRequiredToRelayRcptHook: result= (DENY
Connected)
INFO   | jvm 1    | 2023/07/10 21:21:10 | 2023-07-10 21:21:10,586 INFO  |
org.apache.james.protocols.netty.BasicChannelUpstreamHandler | Connection
closed for 192.168.10.10
INFO   | jvm 1    | 2023/07/10 21:21:10 | 2023-07-10 21:21:10,963 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-NOOP: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:10 | 2023-07-10 21:21:10,966 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-GETQUOTAROOT: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:11 | 2023-07-10 21:21:10,980 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-FETCH: 8 ms.
INFO   | jvm 1    | 2023/07/10 21:21:13 | 2023-07-10 21:21:13,031 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-IDLE: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:34 | 2023-07-10 21:21:34,832 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-APPEND: 34 ms.
INFO   | jvm 1    | 2023/07/10 21:21:34 | 2023-07-10 21:21:34,837 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-NOOP: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:35 | 2023-07-10 21:21:35,094 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-NOOP: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:35 | 2023-07-10 21:21:35,100 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-GETQUOTAROOT: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:35 | 2023-07-10 21:21:35,117 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-FETCH: 14 ms.
INFO   | jvm 1    | 2023/07/10 21:21:35 | 2023-07-10 21:21:35,197 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-FETCH: 16 ms.
INFO   | jvm 1    | 2023/07/10 21:21:35 | 2023-07-10 21:21:35,479 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-STORE: 73 ms.
INFO   | jvm 1    | 2023/07/10 21:21:35 | 2023-07-10 21:21:35,528 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-FETCH: 13 ms.
INFO   | jvm 1    | 2023/07/10 21:21:36 | 2023-07-10 21:21:35,987 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-LOGOUT: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:36 | 2023-07-10 21:21:35,987 INFO  |
org.apache.james.imapserver.netty.ImapChannelUpstreamHandler | Connection
closed for 192.168.10.10
INFO   | jvm 1    | 2023/07/10 21:21:47 | 2023-07-10 21:21:47,598 INFO  |
org.apache.james.imapserver.netty.ImapChannelUpstreamHandler | Connection
established from 192.168.10.10
INFO   | jvm 1    | 2023/07/10 21:21:47 | 2023-07-10 21:21:47,613 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-CAPABILITY: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:47 | 2023-07-10 21:21:47,615 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-AUTHENTICATE: 0 ms.
INFO   | jvm 1    | 2023/07/10 21:21:47 | 2023-07-10 21:21:47,623 INFO  |
org.apache.james.metrics.logger.DefaultMetricFactory | Time spent in
IMAP-CAPABILITY: 0 ms.

After this nothing further seems to be happening with my attempt to send an
email, from my laptop - 192.168.10.10, until I shut down the James server.
Then I saw 8 lines, all repeating the same thing -

INFO   | jvm 1    | 2023/07/10 21:22:06 | 2023-07-10 21:22:06,272 INFO  |
org.apache.james.imapserver.netty.ImapChannelUpstreamHandler | Connection
closed for 192.168.10.10

Dunno if this is helpful or not, hope so...     Marc...

>
> Jean
>
>
>
>
>
> On Mon, Jul 10, 2023 at 7:59 PM Marc Chamberlin <[email protected]
> >
> wrote:
>
> > Jean Helou - Thanks for your help and suggestions, much appreciated!  OK,
> > I stopped the James server, deleted all log files for James, restarted
> the
> > server, and then tried to send an email. Attached you will find the
> > james-server-sample.log file that captured what happened.  HTHs...
> >
> > On Sat, Jul 8, 2023 at 12:14 AM Jean Helou <[email protected]> wrote:
> >
> >> Hello marc
> >>
> >> You wouldn't happen to have a session output and/or logs.
> >> It makes diagnosing the problem much easier and would help pinpoint the
> >> configuration setting that's incorrect.
> >>
> >> Have you changed the mailet container config by any chance ?
> >>
> >
> > Yes, there has been some changes made, but nothing out of the ordinary,
> as
> > far as I can remember, such as setting the postmaster email address etc.,
> > Tell you what, I will attach the mailetcontainer as well, with some
> > sensitive information removed or obscured.
> >
> > Again, HTHs, and thanks for your thoughts and taking the time to
> > reply..    Marc...
> >
> >>
> >>
> >>
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: [email protected]
> > For additional commands, e-mail: [email protected]
>