suddenly 'User unknown'?
Charles Bradshaw
charles.bradshaw at ntlworld.com
Fri Nov 30 10:34:12 EST 2018
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 at 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 at 01:00:00
>> Nov 30 13:01:26 dell2600-1 cyrus/imaps[8645]: USAGE
>> brad at 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]
>> brad at 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/brad at 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 brad at bradcan.homelinux.com :
>>
>> Nov 30 12:59:48 dell2600-1 sendmail[9882]: wAUCxmBS009882:
>> to=brad at 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=<brad at 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 at dell2600-1 brad]# ps -A | grep lmtp
10146 ? 00:00:00 lmtpd
[root at 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 at 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:<brad at 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 brad at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.andrew.cmu.edu/pipermail/info-cyrus/attachments/20181130/5f44fb8e/attachment-0001.html>
More information about the Info-cyrus
mailing list