POP3 polling: understanding dovecot log

Support
1

I’m catching up with POP3 polling and replaying by email features and starting to understand them.

But I’m falling at explaining what our POP3 server is recording in the log when Discourse connects. Could you help me to explain the paired lines RETR/access recorded in the POP3 server log every time Discourse connects to it? It happens, as expected by the value of pop3 polling period mins, every 5 minutes.

In the attached file (21.2 KB), the lines recorded since the activation of both features and the first poll action.

Thanks for your help!

2

(How is this a Discourse question and not a Dovecot question?)

It simply means Discourse is retrieving the mails in your mailbox, one by one.

3

I hesitate between asking here and looking for help from Dovecot forum. I asked here because it is Discourse polling email from the server. Your answer helped me to match the number of “paired lines”, with the number of messages available on the server. I don’t understand yet why sometimes the number of paired lines is exactly the number of messages in the inbox, but other times is just 36

Looking now to Dovecot community looking for more information: I need to get a full explanation about the log to be allowed to use Discourse POP3 features.

Thank you very much for your help.

1 Like
4

Are you sure the 36 is caused by Discourse and not by for instance roundcube or another email client which is retrieving mails page-by-page?

5

As sure as a newbie using summer to improve his skills can be! Thanks for considering the issue.

I think RoundCube is using IMAP here. The new attachment (9.8 KB) includes an n=36 series. It reproduces every 5 minutes. That is mainly why I’m guessing is Discourse-related. I’m not able yet to understand when n is equal to the number of messages in premise’s account inbox.

Thanks!

6

I’m now surer about the origin and After reading RFC 1939 and being able to access rails c to work with library net/pop at least for some basic actions.

[10] pry(main)> Net::POP3.enable_ssl(OpenSSL::SSL::VERIFY_NONE)
=> {:verify_mode=>0}
[11] pry(main)> pop = Net::POP3.new('x.y.z')
=> #<Net::POP3 x.y.esz open=false>
[12] pry(main)> pop.start('premises', 'xxxxxxxxx')
=> #<Net::POP3 x.y.z: open=true>
[13] pry(main)> pop.n_mails()
=> 103

What I’m not able to explain is why some polling cycles read only 36 messages. The last access is always UID=36.

Aug 19 15:46:00 igfae dovecot: pop3(premises): Debug: Mailbox INBOX: Opened mail UID=36 because: access
Aug 19 15:46:00 igfae dovecot: pop3(premises): Debug: Mailbox INBOX: Opened mail UID=36 because: RETR

This number was not modified in spite of there are now more messages in the account.

Could you help me find an explanation to this behavior? Security staff at our center don’t like to have running software generating logs that we can not explain! Thanks!

7

However tempting this is - since I don’t like things I don’t understand either - I think this is a useless exercise since there is not an actual problem.

I did quickly check the source code last time and I couldn’t find anything there.
I suggest you lower the log level…

8

Logging is another topic I have a lot to learn about!

In the current /var/log/maillog file of our mail server, 30644 lines out of 36467 are Dovecot-related. Discourse is the only service using Dovecot in our organization. Although many people are on holidays, 84% of the records depicts Discourse email activity.

I have no control at all about what the mail server register. I can only read it. Thus, I could only modify what information Discourse/Dovecot are sending. Most of the lines include Debug. So, I guess the login configuration in our Discourse instance is sending debug information to the mail server.

How could I modify this behavior?

Accept my apologies in advance if I have a clear misunderstanding of how logging process works! Thanks!

9

No, the mail server is configured to log at “debug” level.

What is happening is the following:

  • the dovecot instance in your organization has been configured to log at the debug level. The debug level is meant for advanced troubleshooting and requires deep insight into the workings of the dovecot software. Since there is no problem, there is no need for troubleshooting, and since there is no need for troubleshooting the log level can be set to a lower (less verbose) level.
  • Your security staff in your center complains that they do not understand the logs. This is because understanding these logs requires deep insight into the workings of the dovecot software, which they don’t have.

Hence the solution: the staff running the dovecot software should change the log level.

This is not something they should complain about to the people using the dovecot software (i.e. you). It is something they or their staff colleagues did.

10

They did it! The log is much cleaner and informative now.

Thank you very much for your explanation. It is much easier to dialog with a good description and analysis of the situation. I can understand all the security concerns as we faced some hard situations in the last couple of years. I accept the exercise of struggling for an explanation but, without your help and the help of others volunteering here and there, it won’t be possible for people like me, with few IT skills, to use, and promote the use, of great tools like Discourse.

Furthermore, I will move now to other doubts related with email settings. Thank you very much!

1 Like