Username during authentication empty

[darealShadow]

Hi,

I have setup z-push and started testing the config with the imap backend. I checked password and username through an openssl connection to make sure I cover the obvious issues first. However, that did not lead to the desired result and each time I try to sync the mailbox with an android phone (older android version 6.0.1) I see the "Getting your messages..." screen but nothing further happens. The logs from Dovecot indicate, that after the username is sent and everything works fine. There are no error logs from z-push-error.log and the z-push.log indicates everything worked as designed.

However, as I am not getting my emails (I have 12 test emails in my inbox) synchronized, it does not work as designed. One error I can see is in line 23. The missing permissions to the folder /proc/self/io could cause an issue. I have no clue how to address that yet.

One other setup step I was unsure of was the DNS section of the config.php from the backend/imap folder. I don't believe that I need this setup completed but am not sure either. Any pointers? Why would I need that section configured? What is that section for?

Dovecot Log
01 Aug 31 23:55:38 auth: Debug: auth client connected (pid=1779)
02 Aug 31 23:55:38 auth: Debug: client in: AUTH 1 PLAIN service=imap secured session=nkJGeQghErIK9MJ6 lip=10.244.126.45 rip=10.244.194.122 lport=143 rport=45586
03 Aug 31 23:55:38 auth: Debug: client passdb out: CONT 1
04 Aug 31 23:55:38 auth: Debug: client in: CONT<hidden>
05 Aug 31 23:55:38 auth: Debug: sql(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): Performing passdb lookup
06 Aug 31 23:55:38 auth-worker(1777): Debug: conn unix:auth-worker (pid=15,uid=90): auth-worker<2>: Handling PASSV request
07 Aug 31 23:55:38 auth-worker(1777): Debug: conn unix:auth-worker (pid=15,uid=90): auth-worker<2>: sql(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): Performing passdb lookup
08 Aug 31 23:55:38 auth-worker(1777): Debug: conn unix:auth-worker (pid=15,uid=90): auth-worker<2>: sql(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): query: SELECT username as user, aes_decrypt(password,"DECRYPTIONPASSWORD")as password FROM virtual_users WHERE username='PETER'
09 Aug 31 23:55:38 auth-worker(1777): Debug: mysql(mariadb-galera-cluster): Finished query 'SELECT username as user, aes_decrypt(password,"DECRYPTIONPASSWORD")as password FROM virtual_users WHERE username='PETER'' in 1 msecs
10 Aug 31 23:55:38 auth-worker(1777): Debug: conn unix:auth-worker (pid=15,uid=90): auth-worker<2>: sql(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): username changed peter -> PETER
11 Aug 31 23:55:38 auth: Debug: sql(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): username changed peter -> PETER
12 Aug 31 23:55:38 auth: Debug: sql(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): Finished passdb lookup
13 Aug 31 23:55:38 auth: Debug: auth(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): Auth request finished
14 Aug 31 23:55:38 auth: Debug: client passdb out: OK 1 user=PETER
15 Aug 31 23:55:38 auth-worker(1777): Debug: conn unix:auth-worker (pid=15,uid=90): auth-worker<2>: sql(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): Finished passdb lookup
16 Aug 31 23:55:38 auth-worker(1777): Debug: conn unix:auth-worker (pid=15,uid=90): auth-worker<2>: Finished
17 Aug 31 23:55:38 auth: Debug: master in: REQUEST 1983381505 1779 1 27432ca8094aaef3f9878607b881bc9e session_pid=1780 request_auth_token
18 Aug 31 23:55:38 auth: Debug: static(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): Performing userdb lookup
19 Aug 31 23:55:38 auth: Debug: static(PETER,10.244.194.122,<nkJGeQghErIK9MJ6>): Finished userdb lookup
20 Aug 31 23:55:38 auth: Debug: master userdb out: USER 1983381505 PETER uid=5000 gid=5000 home=/mail/PETER auth_mech=PLAIN auth_token=d10ed3bf293b8c081cec413d939cede8e289461c
21 Aug 31 23:55:38 imap-login: Info: Login: user=<PETER>, method=PLAIN, rip=10.244.194.122, lip=10.244.126.45, mpid=1780, secured, session=<nkJGeQghErIK9MJ6>
22 Aug 31 23:55:38 imap(PETER)<1780><nkJGeQghErIK9MJ6>: Debug: Effective uid=5000, gid=5000, home=/mail/PETER
23 Aug 31 23:55:38 imap(PETER)<1780><nkJGeQghErIK9MJ6>: Debug: open(/proc/self/io) failed: Permission denied
24 Aug 31 23:55:38 imap(PETER)<1780><nkJGeQghErIK9MJ6>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/PETER/
25 Aug 31 23:55:38 imap(PETER)<1780><nkJGeQghErIK9MJ6>: Debug: maildir++: root=/mail/PETER, index=, indexpvt=, control=, inbox=/mail/PETER, alt=
26 Aug 31 23:55:38 imap(PETER)<1780><nkJGeQghErIK9MJ6>: Debug: Mailbox INBOX: Mailbox opened
27 Aug 31 23:55:38 imap(PETER)<1780><nkJGeQghErIK9MJ6>: Debug: Mailbox Sent: Mailbox opened
28 Aug 31 23:55:38 imap(PETER)<1780><nkJGeQghErIK9MJ6>: Info: Disconnected: Logged out in=479 out=2827 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
29 Aug 31 23:55:38 imap(PETER)<1780><nkJGeQghErIK9MJ6>: Debug: User session is finished

z-push.log
31/08/2024 23:55:36 [ 11] [ INFO] [PETER] cmd='Ping' memory='1.65 MiB/2.00 MiB' time='146.23s' devType='Android' devId='androidc2039314481' getUser='PETER' from='10.244.126.50' idle='146s' version='2.7.3 ' method='POST' httpcode='200'
31/08/2024 23:56:11 [ 9] [ INFO] [PETER] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 480 seconds)
31/08/2024 23:56:11 [ 9] [ INFO] [PETER] ExportChangesDiff->InitializeExporter(): Found '6' changes for 'hierarchy'
31/08/2024 23:56:12 [ 9] [ INFO] [[PETER] BackendIMAP->GetMessageList('INBOX','1724565371'): 0 result for the search or error: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
31/08/2024 23:56:12 [ 9] [ INFO] [PETER] ExportChangesDiff->InitializeExporter(): Found '0' changes for '4c154b00'
31/08/2024 23:56:12 [ 9] [ INFO] [PETER] BackendIMAP->GetMessageList('Sent','1724565372'): 0 result for the search or error: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
31/08/2024 23:56:12 [ 9] [ INFO] [PETER] ExportChangesDiff->InitializeExporter(): Found '0' changes for '4de82906'
31/08/2024 23:57:12 [ 7] [ INFO] [PETER] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 480 seconds)
31/08/2024 23:57:12 [ 7] [ INFO] [PETER] ExportChangesDiff->InitializeExporter(): Found '6' changes for 'hierarchy'
31/08/2024 23:57:12 [ 7] [ INFO] [PETER] BackendIMAP->GetMessageList('INBOX','1724565432'): 0 result for the search or error: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
31/08/2024 23:57:12 [ 7] [ INFO] [PETER] ExportChangesDiff->InitializeExporter(): Found '0' changes for '4c154b00'
31/08/2024 23:57:12 [ 7] [ INFO] [PETER] BackendIMAP->GetMessageList('Sent','1724565432'): 0 result for the search or error: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
31/08/2024 23:57:12 [ 7] [ INFO] [PETER] ExportChangesDiff->InitializeExporter(): Found '0' changes for '4de82906'

config.php from the backend/imap folder
// DSN: formatted PDO connection string
// mysql:host=xxx;port=xxx;dbname=xxx
// USER: username to DB
// PASSWORD: password to DB
// OPTIONS: array with options needed
// QUERY: query to execute
// FIELDS: columns in the query
// FROM: string that will be the from, replacing the column names with the values
define('IMAP_FROM_SQL_DSN', '');
define('IMAP_FROM_SQL_USER', '');
define('IMAP_FROM_SQL_PASSWORD', '');
define('IMAP_FROM_SQL_OPTIONS', serialize(array(PDO::ATTR_PERSISTENT => true)));
define('IMAP_FROM_SQL_QUERY', "select first_name, last_name, mail_address from users where mail_address = '#username@#domain'");
define('IMAP_FROM_SQL_FIELDS', serialize(array('first_name', 'last_name', 'mail_address')));
define('IMAP_FROM_SQL_EMAIL', '#mail_address');
define('IMAP_FROM_SQL_FROM', '#first_name #last_name <#mail_address>');
define('IMAP_FROM_SQL_FULLNAME', '#first_name #last_name');

[darealShadow]

Please ignore this discussion. I realized that I needed to change the sync period to "All time" and the sync started working. I had a few other options set wrong but once I applied the sync changes to the account, the email sync worked.