Patrick, Javier, at last progress. Brilliant. :-) See below.
On 30/11/2018 14:16, Patrick Boutilier wrote:
> On 11/30/18 10:00 AM, Charles Bradshaw via Info-cyrus wrote:
>> Javier
>>
>> On 30/11/2018 11:49, Javier Angulo wrote:
>>> On 11/29/18 8:00 PM, Charles Bradshaw via Info-cyrus wrote:
>>>> Now you tell me is cyrus syslog being sent to /var/log/maillog? Or
>>>> should it be going to /var/imapd.log as the configuration files, man
>>>> pages and cyrus installation guides ( found here:
>>>> https://www.cyrusimap.org/imap/installing.html ) say it should?
>>> I believe there is no "syslog_facility:" option in cyrus 2.4 (at
>>> least I
>>> was unable to find it). You can configure it in cyrus3 and maybe in
>>> cyrus 2.5.
>> I removed syslog_facility from imapd.conf
>>> So in /etc/imapd.conf I would remove the syslog_facility line and set:
>>> syslog_prefix: cyrus
>> Has no effect: present or not, or changed to test.
>>> And in /etc/rsyslog.conf:
>>> mail.* -/var/log/maillog
>> Has always been in my rsyslog.conf
>>>
>>> Restart rsyslog and check logs for cyrus/something ...
>>
>> # /etc/init.d/rsyslog restart
>>
>> # service sendmail restart
>>
>> Now when I connect (from another host) using Thunderbird Mail I see in
>> /etc/maillog:
>>
>> Nov 30 13:01:02 dell2600-1 sendmail[9865]: NOQUEUE: stopping daemon,
>> reason=signal
>> Nov 30 13:01:02 dell2600-1 sendmail[9950]: starting daemon (8.14.4):
>> SMTP+queueing@01:00:00
>> Nov 30 13:01:02 dell2600-1 sendmail[9950]: STARTTLS: CRLFile missing
>> Nov 30 13:01:03 dell2600-1 sendmail[9950]: STARTTLS=server,
>> Diffie-Hellman init, key=1024 bit (1)
>> Nov 30 13:01:03 dell2600-1 sendmail[9950]: STARTTLS=server, init=1
>> Nov 30 13:01:03 dell2600-1 sendmail[9950]: started as:
>> /usr/sbin/sendmail -bd -q1h
>> Nov 30 13:01:03 dell2600-1 sm-msp-queue[9960]: starting daemon (8.14.4):
>> queueing@01:00:00
>> Nov 30 13:01:26 dell2600-1 cyrus/imaps[8645]: USAGE
>> b...@bradcan.homelinux.com user: 0.141978 sys: 0.087986
>> Nov 30 13:05:59 dell2600-1 cyrus/imaps[8743]: starttls: TLSv1.2 with
>> cipher AES128-SHA (128/128 bits new) no authentication
>> Nov 30 13:05:59 dell2600-1 cyrus/imaps[8743]: login: [192.168.0.6]
>> b...@bradcan.homelinux.com CRAM-MD5+TLS User logged in
>> SESSIONID=<cyrus-8743-1543583158-1>
>> Nov 30 13:05:59 dell2600-1 cyrus/imaps[8743]: client id: "name"
>> "Thunderbird" "version" "60.2.1"
>>
>> Hum.. cyrus/imaps sends logging to /etc/maillog
>>
>> I think it is absolutely clear:
>>
>> 1 - where cyrus syslog goes to is a red herring. It goes to, and has
>> always gone to /var/maillog. It is simply that the prefix 'cyrus' only
>> appears for cyrus imap transactions and other sendmail is labeled
>> 'sendmail'
>>
>> 2 - imapd is working fine: allows brad.bradcan.homelinux.com to connect
>> an email client. Also to move email from one mailbox to another. The
>> proof is that since enabling telemetry logging
>> /var/lib/imap/log/b...@bradcan.homelinux.com/ reflects imap
>> transactions.
>>
>> 3 - A problem remains with LMTP. as is clearly evident from 'User
>> unknown' appearing in maillog.
>>
>> My original question remains: How do I diagnose this when a test email
>> is sent to b...@bradcan.homelinux.com :
>>
>> Nov 30 12:59:48 dell2600-1 sendmail[9882]: wAUCxmBS009882:
>> to=b...@bradcan.homelinux.com, delay=00:00:00, xdelay=00:00:00,
>> mailer=cyrusv2, pri=32701, relay=localhost [[UNIX:
>> /var/lib/imap/socket/lmtp]], dsn=5.1.1, stat=User unknown
>
>
> I think why people are concentrating on the logging is that there
> should be lmtp entries in your logs to indicate what the issue is. Are
> there any lmtp entries in either /etc/maillog or /var/log/maillog ?
The only lmtp entries are the one shown above.
I do # cat /var/log/maillog | grep lmtp
Nov 30 12:59:48 dell2600-1 sendmail[9882]: wAUCxmBR009882:
to=<b...@bradcan.homelinux.com>, delay=00:00:00, xdelay=00:00:00,
mailer=cyrusv2, pri=31677, relay=localhost [[UNIX:
/var/lib/imap/socket/lmtp]], dsn=5.1.1, stat=User unknown
>
>
> Another option is to limit lmtpd to one process and strace it.
If I do:
[root@dell2600-1 brad]# ps -A | grep lmtp
10146 ? 00:00:00 lmtpd
[root@dell2600-1 brad]# strace -p 10146
Process 10146 attached
accept(4, 0, NULL) = 11
fcntl64(10, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 0
write(3, "\2\0\0\0\242'\0\0", 8) = 8
dup2(11, 0) = 0
dup2(11, 1) = 1
dup2(11, 2) = 2
close(11) = 0
write(3, "\3\0\0\0\242'\0\0", 8) = 8
time(NULL) = 1543588732
getpeername(0, {sa_family=AF_LOCAL, NULL}, [2]) = 0
open("/var/lib/imap/log/postman/lmtpunix-10146",
O_WRONLY|O_CREAT|O_APPEND, 0644) = -1 ENOENT (No such file or directory)
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "220 dell2600-1.bradcan.homelinux"..., 94) = 94
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 999704})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "LHLO bradcan.homelinux.com\r\n", 4096) = 28
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250-dell2600-1.bradcan.homelinux"..., 139) = 139
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 997839})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "MAIL From:<brad@bradcan.homelinu"..., 4096) = 49
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250 2.1.0 ok\r\n", 14) = 14
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 998503})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "RCPT To:<brad>\r\nDATA\r\n", 4096) = 22
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
fcntl64(6, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
fstat64(6, {st_mode=S_IFREG|0600, st_size=22204, ...}) = 0
stat64("/var/lib/imap/mailboxes.db", {st_mode=S_IFREG|0600,
st_size=22204, ...}) = 0
fcntl64(6, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "550-Mailbox unknown. Either the"..., 174) = 174
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 999990})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "RSET\r\n", 4096) = 6
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250 2.0.0 ok SESSIONID=<cyrus-10"..., 51) = 51
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 932516})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "RSET\r\n", 4096) = 6
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250 2.0.0 ok SESSIONID=<cyrus-10"..., 51) = 51
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 999995})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "MAIL From:<> SIZE=1677\r\n", 4096) = 24
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250 2.1.0 ok\r\n", 14) = 14
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 999524})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "RCPT To:<brad>\r\nDATA\r\n", 4096) = 22
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
fcntl64(6, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
fstat64(6, {st_mode=S_IFREG|0600, st_size=22204, ...}) = 0
stat64("/var/lib/imap/mailboxes.db", {st_mode=S_IFREG|0600,
st_size=22204, ...}) = 0
fcntl64(6, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "550-Mailbox unknown. Either the"..., 174) = 174
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 999612})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "RSET\r\n", 4096) = 6
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250 2.0.0 ok SESSIONID=<cyrus-10"..., 51) = 51
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 946078})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "RSET\r\n", 4096) = 6
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250 2.0.0 ok SESSIONID=<cyrus-10"..., 51) = 51
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 999994})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "MAIL From:<> SIZE=2701\r\n", 4096) = 24
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250 2.1.0 ok\r\n", 14) = 14
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 999927})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "RCPT To:<brad>\r\nDATA\r\n", 4096) = 22
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
fcntl64(6, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
fstat64(6, {st_mode=S_IFREG|0600, st_size=22204, ...}) = 0
stat64("/var/lib/imap/mailboxes.db", {st_mode=S_IFREG|0600,
st_size=22204, ...}) = 0
fcntl64(6, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "550-Mailbox unknown. Either the"..., 174) = 174
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 999987})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "RSET\r\n", 4096) = 6
open("/var/lib/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file
or directory)
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
write(1, "250 2.0.0 ok SESSIONID=<cyrus-10"..., 51) = 51
time(NULL) = 1543588732
select(1, [0], NULL, NULL, {360, 0}) = 1 (in [0], left {359, 871969})
time(NULL) = 1543588732
time(NULL) = 1543588732
read(0, "QUIT\r\n", 4096) = 6
write(1, "221 2.0.0 bye\r\n", 15) = 15
open("/dev/null", O_RDWR) = 11
shutdown(0, SHUT_RD) = 0
dup2(11, 0) = 0
shutdown(1, SHUT_RD) = 0
dup2(11, 1) = 1
shutdown(2, SHUT_RD) = 0
dup2(11, 2) = 2
close(11) = 0
write(3, "\1\0\0\0\242'\0\0", 8) = 8
rt_sigaction(SIGALRM, {0x80113f00, [], SA_RESETHAND}, NULL, 8) = 0
rt_sigaction(SIGQUIT, {0x80113f00, [], SA_RESETHAND}, NULL, 8) = 0
rt_sigaction(SIGHUP, {0x80113f00, [], SA_RESTART|SA_RESETHAND}, NULL, 8) = 0
rt_sigaction(SIGINT, {0x80113f00, [], SA_RESTART|SA_RESETHAND}, NULL, 8) = 0
alarm(74) = 0
fcntl64(10, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) =
? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=1698768,
ptr=0x19ebd0}} ---
sigreturn() (mask []) = -1 EINTR (Interrupted system call)
munmap(0xb7700000, 16384) = 0
close(5) = 0
munmap(0xb76f8000, 32768) = 0
close(6) = 0
munmap(0xb76f4000, 16384) = 0
close(7) = 0
munmap(0xb76f0000, 16384) = 0
close(8) = 0
exit_group(0) = ?
+++ exited with 0 +++
I don't understand the above! Except there are a number of lines like:
open("/var/lib/imap/log/postman/lmtpunix-10146",
O_WRONLY|O_CREAT|O_APPEND, 0644) = -1 ENOENT (No such file or directory)
Does any of the above explain 'User unknown', apart from fact that lmtp
quit with SIGALRM
I created /var/lib/imap/log/postman then when the test email is sent
/var/lib/imap/log/postman contains this message:
---------- postman Fri Nov 30 15:04:47 2018
>1543590287>220 dell2600-1.bradcan.homelinux.com Cyrus LMTP
v2.4.17-Invoca-RPM-2.4.17-7.el6 server ready
<1543590287<LHLO bradcan.homelinux.com
>1543590287>250-dell2600-1.bradcan.homelinux.com
250-8BITMIME
250-ENHANCEDSTATUSCODES
250-PIPELINING
250-SIZE
250-AUTH EXTERNAL
250 IGNOREQUOTA
<1543590287<MAIL From:<b...@bradcan.homelinux.com> SIZE=653
>1543590287>250 2.1.0 ok
<1543590287<RCPT To:<brad>
DATA
>1543590287>550-Mailbox unknown. Either there is no mailbox associated
with this
550-name or you do not have authorization to see it.
550 5.1.1 User unknown
...
Now I'm guessing, since user b...@bradcan.homelinux.com does exist and
is working then it must be authorization.
So why is authorization failing after years of working? How do I test
authorization?
>
>
>
>
>
>
>>
>> Thanks for your patience.
>>
>>>
>>> Cheers
>>> ----
>>> Cyrus Home Page: http://www.cyrusimap.org/
>>> List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/
>>> To Unsubscribe:
>>> https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus
>> ----
>> Cyrus Home Page: http://www.cyrusimap.org/
>> List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/
>> To Unsubscribe:
>> https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus
>>
>
>
> ----
> Cyrus Home Page: http://www.cyrusimap.org/
> List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/
> To Unsubscribe:
> https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus
----
Cyrus Home Page: http://www.cyrusimap.org/
List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/
To Unsubscribe:
https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus
