The zimbra backend is effectively equivalent to a web user connection to zimbra using the standard zimbra webmail client. The backend performs a curl request to the same HTTP(S) address as the webmail does when it issues requests.
Thanks. This is quite helpful. I have a much better understanding with just that simple explanation. In this case, I’m pretty sure I have encountered a Zimbra bug. We shall see…
There is nothing that can take place without authentication - so if any client has gotten as far as provisioning then they have been authenticated.
This seems to be the case. Then somewhere around 10:43, I see complaints in z-push.log:
z-push.log:30/08/2017 10:43:24  [ERROR] [firstname.lastname@example.org] [sec1efd804e75816] LoopDetection->ProcessLoopDetectionPreviousConnectionFailed(): Command 'Sync' at 30/08/2017 10:42:18 with pid '22964' terminated unexpectedly or is still running.
z-push.log:30/08/2017 10:43:24  [ERROR] [email@example.com] [sec1efd804e75816] Please check your logs for this PID and errors like PHP-Fatals or Apache segmentation faults and report your results to the Z-Push dev team.
Have you captured a detailed debug log?
Yes. I have z-push.log, z-push-error.log, logged at the WBXML level. I have some php logs, and some zimbra logs, as well. They are all trimmed to the correct time frame to reduce the noise, but not within that time frame to prevent obscuring notice of external influences. I also have operator log, which details my user commands with time stamps.
Use the $specialLogUsers array in the z-push config file to capture detailed logs for just that user. If you turn the z-push logging up to WBXML level in the z-push config file for the specialLogUsers it will provide all of the z-push comings and goings.
Done. hollie_tclc_org.log hollie_tclc_org.log.formatted has the JSON formated in a human readable form.
In addition if you then turn ZIMBRA_DEBUG on (or set it to the particular username) in the zimbra config.php file then you will also get all of the zimbra SOAP requests and responses logged.
This is new information for me, and I have not done this. I will repeat my experiment with this setting, but I suspect that it is now superfluous. It is clear to me that the complaints in z-push.log are because that process has become unresponsive. I looked and it was still running. I also see hints about mailbox locking, so I think that somehow, after successfully returning the folder structure and beginning to return the contents, the mailbox is locked and blocks subsequent accesses.
This deadlock will be on the “Authenticate with External LDAP” path in zimbra, because ALL such users fail, and my one Zimbra authenticate user succeeds.
I am sure this is succeeding in every case. I am sure your issue is further down the line, and I suspect it is folder/message volume related somehow.
I have been quite sure since we first started working on this that it was not capacity related simply because the user that works, cjm, has a much higher capacity requirement than the user that fails, mhr. In fact, I have also tried experimental users with trivial amounts of volume, which also fail. However, since you clearly know more about this than I do, I have not asserted my belief strongly. I think we will see that it is a Zimbra logic bug causing a deadlock.
I have a set of logs that constitute about four megs and might be interesting to you, if you would like them, and if you instruct me how, I will provide them to you. As the operator, I kept a timestamped log of my actions. It is included below:
10.1.1.100: law.tclc.org (mhr desktop) 10.1.1.103: code.tclc.org (cjm desktop) 10.1.1.105: Android Cell Phone (mhr handheld) 10.1.1.12: mail.tclc.org (Zimbra Server) 2017.08.30 10:31:01 cleared logs 2017.08.30 10:31:54 Powered down white tablet to reduce noise 2017.08.30 10:33:36 Powered up white cell phone 201708.30 10:34:14 invoke phone email application 2017.08.30 10:36:01 "Next" (email application on phone) 2017.08.30 10:36:12 Server could not finish -- Operator Error: incorrect domain name (mail.itclc.org) 2017.08.30 10:36:49 "Next" (email application on phone) 2017.08.30 10:36:55 "Continue" (email application on phone) 2017.08.30 10:37:46 authentication failed -- Operator Error: incorrect username (firstname.lastname@example.org) 2017.08.30 10:38:04 "Next" (email application on phone) 2017.08.30 10:38:09 "Continue" (email application on phone) 2017.08.30 10:39:29 "Next" (email application on phone) (provisioning) 2017.08.30 10:39:51 Device administrator 2017.08.30 10:41:47 Policies deployed 2017.08.30 10:43:01 Request contents of "inbox" ... endless "Loading..." 2017.08.30 10:44:48 exit mail application 2017.08.30 10:47:06 last of z-push-top threads dissappears 2017.08.30 11:06:29 stop zimbra, php-fpm