Dovecot is not locating messages in maildir, how to interpret debug log?

Question

I'm setting up Postfix and Dovecot on Ubuntu Server 18.04.

Using Telnet to test the setup, I am able to log in with the desired email name, but the test is not finding any emails in the associated account. As far as I can tell, I've got the correct mail_location setting in my configuration files.

The test (from Dovecot Documentation's TestInstallation page) has the user log in, then run the following command:

b select inbox

The documentation test example shows the following as expected results if successful,

b select inbox
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
* 1 EXISTS
* 1 RECENT
* OK [UIDVALIDITY 1106186941] UIDs valid
* OK [UIDNEXT 2] Predicted next UID
b OK [READ-WRITE] Select completed.

But I get the following

b select inbox
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
* 0 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1575837513] UIDs valid
* OK [UIDNEXT 1] Predicted next UID
b OK [READ-WRITE] Select completed (0.001 + 0.000 secs).

I have a good half dozen emails in /var/mail/vhosts/adonax.com/phil/new, including one sent and received just prior to doing this test (which I verified with a cat command)

Following is the debug log generated for the session.

First I log and run the command a login "phil@adonax.com" "fakepassword"

Dec 10 13:10:41 adonax dovecot: auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Dec 10 13:10:41 adonax dovecot: auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so
Dec 10 13:10:41 adonax dovecot: auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat
Dec 10 13:10:41 adonax dovecot: auth: Debug: passwd-file /etc/dovecot/users: Read 2 users in 0 secs
Dec 10 13:10:41 adonax dovecot: auth: Debug: auth client connected (pid=10539)

So far so good, yes?

Second I run the test command b select inbox and get this result in the log file:

Dec 10 13:10:53 adonax dovecot: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured#011session=79iD8l+ZaJomADwBAADAPAA8kv/+k1+g#011lip=2600:3c01::f03c:92ff:fe93:5fa0#011rip=2600:3c01::f03c:92ff:fe93:5fa0#011lport=143#011rport=39528#011resp=AHBoaWxAYBRvbmFvbQBWtlNHmYB3b4LmN3Jk (previous base64 data may contain sensitive data)
Dec 10 13:10:53 adonax dovecot: auth: Debug: passwd-file(phil@adonax.com,2600:3c01::f03c:92ff:fe93:5fa0,<79iD8l+ZaJomADwBAADAPAA8kv/+k1+g>): lookup: user=phil@adonax.com file=/etc/dovecot/users
Dec 10 13:10:53 adonax dovecot: auth: Debug: client passdb out: OK#0111#011user=phil@adonax.com
Dec 10 13:10:53 adonax dovecot: auth: Debug: master in: REQUEST#0112679242753#01110539#0111#01118bfa959ad3d6d0c377ed53b2f0b3617#011session_pid=10541#011request_auth_token
Dec 10 13:10:53 adonax dovecot: auth: Debug: passwd-file(phil@adonax.com,2600:3c01::f03c:92ff:fe93:5fa0,<79iD8l+ZaJomADwBAADAPAA8kv/+k1+g>): lookup: user=phil@adonax.com file=/etc/dovecot/users
Dec 10 13:10:53 adonax dovecot: auth: Debug: master userdb out: USER#0112679242753#011phil@adonax.com#011uid=5000#011gid=5000#011home=/var/mail/vhosts/adonax.com/phil#011auth_token=04eb2747ef24bd23d6355aeb978ef361edbb48a3
Dec 10 13:10:53 adonax dovecot: imap-login: Login: user=<phil@adonax.com>, method=PLAIN, rip=2600:3c01::f03c:92ff:fe93:5fa0, lip=2600:3c01::f03c:92ff:fe93:5fa0, mpid=10541, secured, session=<79iD8l+ZaJomADwBAADAPAA8kv/+k1+g>

Without fully understanding the above, I do see where what I think should be the correct "home" address is specified correctly as home=/var/mail/vhosts/adonax.com/phil I can 'cd' to that directory, and it contains what I assume to be standard subdirectories:

root@adonax:~# ls -al /var/mail/vhosts/adonax.com/phil
total 24
drwxr-sr-x 6 vmail vmail 4096 Dec  8 12:38 .
drwxr-sr-x 3 vmail vmail 4096 Dec  1 19:45 ..
drwx--S--- 2 vmail vmail 4096 Dec  2 23:44 cur
drwx--S--- 2 vmail vmail 4096 Dec 10 12:25 new
drwx--S--- 2 vmail vmail 4096 Dec 10 12:25 tmp
drwx--S--- 3 vmail vmail 4096 Dec  8 12:38 var

Is this an issue somehow related to my session not engaging the vmail user? (If yes, I'll have to backtrack through the guide I'm using to set this up, as to how and why they create a general user specifically for handling email and if it has been done correctly.)

Is the issue maybe something to do with the configuration thinking that I'm making use of a database instead of a simple file with passwords? I see the term userdb in the following line.

Dec 10 13:10:53 adonax dovecot: auth: Debug: master userdb out: USER#0112679242753#011phil@adonax.com#011uid=5000#011gid=5000#011home=/var/mail/vhosts/adonax.com/phil#011auth_token=04eb2747ef24bd23d6355aeb978ef361edbb48a3

Could the fail be related to searching for "inbox" when either the search should be for something else or I've perhaps missed a step in not setting up an explicit "inbox" file folder?

Here are a few lines from 10-mail.conf that were added (instructions to do so coming from the installation guide that I am using).

 mail_location = maildir:~/var/mail/vhosts/adonax.com/phil
 passdb {
   driver = passwd-file
   args = username_format=%u /etc/dovecot/users
 }
 userdb {
   driver = static
   args = uid=vmail gid=vmail home=/var/mail/vhosts/%d/%n
 }

I've created a long post here with a lot of info posted. I hope it is mostly pertinent to the question. I'm happy to add more to answer followup questions.

Answer 1

Found it!

The mail_location setting had a ~ in the address that it shouldn't have had.

Based on that, it was looking in /root/var/mail/... instead of /var/mail/...

The Telnet test on port 143 now works.