Errors spamming in logs
Brought to you by:
gnosbush,
liverpoolfcfan
Menu
▾
▴
1 Attachments
#189 Errors spamming in logs
Hello,
This day, I noticed my phone was hot and lost half of its battery level in just a couple of hours. The application responsible was the calendar.
I looked at the z-push logs and saw that they had been filling up very quickly since 2am. Here's an extract:
21/05/2024 02:44:51 [3735797] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Undefined index: tz (8)
21/05/2024 02:44:51 [3735797] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Trying to access array offset on value of type null (8)
21/05/2024 02:44:53 [3735727] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Undefined index: tz (8)
21/05/2024 02:44:53 [3735727] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Trying to access array offset on value of type null (8)
21/05/2024 02:44:55 [3735821] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Undefined index: tz (8)
21/05/2024 02:44:55 [3735821] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Trying to access array offset on value of type null (8)
[...]
21/05/2024 02:45:11 [3742985] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Undefined index: tz (8)
21/05/2024 02:45:11 [3742985] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Trying to access array offset on value of type null (8)
21/05/2024 02:45:11 [3735797] [ERROR] [userl@example.com] Zimbra->SoapRequest(): SOAP FAULT: Error Code [service.PERM_DENIED]
21/05/2024 02:45:11 [3735797] [ERROR] [userl@example.com] Zimbra->SoapRequest(): SOAP FAULT: Error Reason [permission denied: you do not have the required rights on >
21/05/2024 02:45:11 [3735797] [ERROR] [userl@example.com] Zimbra->SoapRequest(): SOAP Message: <soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
<soap:Header><context xmlns="urn:zimbra">
<authToken>0_175b38c09473d7514df8014a8e2f881cb9eeb952_69643d33363a62643861343039312d666666622d343632662d386262342d6638653833356638353339643>
<session id="145644" /><format type="js" /> <userAgent name="Apple-iPhone12C3/2007.81(...ko5t3o) devip=<REDACTED> ZPZB" version="70.4>
</context></soap:Header>
<soap:Body><CreateAppointmentRequest xmlns="urn:zimbraMail">
<m l="258" d="1716252311000">
<inv>
<comp allDay="0" name="Dummy">
<s d="20240521T024511" tz="UTC"/>
<e d="20240521T031511" tz="UTC"/>
</comp>
</inv>
</m>
</CreateAppointmentRequest></soap:Body>
</soap:Envelope>
21/05/2024 02:45:11 [3735797] [ERROR] [userl@example.com] Zimbra->SoapRequest(): SOAP Response:
21/05/2024 02:45:12 [3735821] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Undefined index: tz (8)
21/05/2024 02:45:12 [3735821] [WARN] [pierre@example.com] /usr/share/z-push/backend/zimbra/zimbra.php:12816 Trying to access array offset on value of type null (8)
21/05/2024 02:45:13 [3735578] [ERROR] [seb@example.com] Zimbra->SoapRequest(): SOAP FAULT: Error Code [service.PERM_DENIED]
21/05/2024 02:45:13 [3735578] [ERROR] [seb@example.com] Zimbra->SoapRequest(): SOAP FAULT: Error Reason [permission denied: you do not have sufficient permissions]
21/05/2024 02:45:13 [3735578] [ERROR] [seb@example.com] Zimbra->SoapRequest(): SOAP Message: <soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
<soap:Header><context xmlns="urn:zimbra">
<authToken>0_d5c3c2d706475696143daffd4c13ce02c0d72862_69643d33363a34623238643963382d626465382d346336352d386530302d3366346239333739373565303>
<session id="145682" /><format type="js" /> <userAgent name="Apple-iPhone16C1/2105.236(...ib8j4k) devip=<REDACTED> ZPZB" version="70.>
</context></soap:Header>
<soap:Body><GetAppointmentRequest id="f1cee433-2398-4939-a250-2a17255db905:1332803" sync="1" xmlns="urn:zimbraMail"/></soap:Body>
</soap:Envelope>
21/05/2024 02:45:13 [3735578] [ERROR] [seb@example.com] Zimbra->SoapRequest(): SOAP Response:
21/05/2024 02:45:13 [3730533] [ERROR] [pierre@example.com] Zimbra->SoapRequest(): SOAP FAULT: Error Code [service.PERM_DENIED]
21/05/2024 02:45:13 [3730533] [ERROR] [pierre@example.com] Zimbra->SoapRequest(): SOAP FAULT: Error Reason [permission denied: you do not have sufficient permissions]
21/05/2024 02:45:13 [3730533] [ERROR] [pierre@example.com] Zimbra->SoapRequest(): SOAP Message: <soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
<soap:Header><context xmlns="urn:zimbra">
<authToken>0_7bc5ed5ba8e42054b2e158a52442d854b2b0b6c3_69643d33363a64623833393832312d653230342d346362652d393932322d3633663633653063323266373>
<session id="145681" /><format type="js" /> <userAgent name="Apple-iPad7C1/2105.219(...d7bq2k) devip=<REDACTED> ZPZB" version="70.4" >
</context></soap:Header>
<soap:Body><GetAppointmentRequest id="f1cee433-2398-4939-a250-2a17255db905:1332801" sync="1" xmlns="urn:zimbraMail"/></soap:Body>
</soap:Envelope>
At the same time, network traffic on the z-push server was high (see attached screenshot).
I noticed events called ‘Dummy’ which I removed, and restarted the z-push server. This solved the problem, but it's the second time this has happened in a month.
Does anyone have any idea where the problem is coming from?
Thanks a lot!
Best regards
First off, you are using a very old version of the backend,
ZPZB version=70.4
You should be using the latest one which is 72.
Secondly, the error messages in the logs are telling you the issue
21/05/2024 02:45:13 [3735578] [ERROR] [seb@example.com] Zimbra->SoapRequest(): SOAP FAULT: Error Code [service.PERM_DENIED]
21/05/2024 02:45:13 [3735578] [ERROR] [seb@example.com] Zimbra->SoapRequest(): SOAP FAULT: Error Reason [permission denied: you do not have sufficient permissions]
You are trying to create an appointment in a calendar folder that you do not have permissions to write to.
The Dummy appointment(s) you mention should only get created if the device does not send across a timezone for an appointment. The backend should create a dummy appointment, grab the timezone from it, and then remove it again. Make sure the account you are syncing has permissions for both creating and deleting appointments.
Hello,
Thanks a lot for your reply. I've updated Zimbra Backend to the release 72.
Indeed, the account in question does not have write access to this calendar, as it is a team calendar shared by several people. When I deactivate the account, the logs become silent again in about ten minutes.
Does this mean that the device of the person who has this account is constantly trying to create an event? Is there a way of letting the device know that the calendar is read-only and that creation requests should not be sent?
Thanks for this clarification about the dummy events, I didn't understand what it was all about.
Best regards
There is no concept of a read-only calendar in ActiveSync. You either need to give everyone write access or educate them to not attempt to create appointments in that calendar.
You may be able to get rid of the bogus appointment by issuing a resync from z-push-admin.php for that user/device. I am not sure if it will work. Failing that, remove the account from the device, then add it back fresh.
Understood. I switched every read-only account to direct CalDAV with Zimbra to manage the issue.
However, I am unable to get rid of errors below. I tried a resync (with z-push-admin) and deleting/re-adding the account to the device.
Does this mean some events are corrupted ? Is there any way to fix them ?
Thanks for your time
Pierre
Possibly, or just originating from a dodgy calendar app.
In the z-push config.php turn on detailed debug information for that user
Look for the define and update the LOGLEVEL to LOGLEVEL_DEVICEID, and add pierre@example.com to the $specialLogUsers array
This should create an additional log file named
pierre_example_com-deviceid.log
This will allow you to see the WBXML messages between the client and the server. You can see what it is tripping over. Assuming you can see a subject you will be able to identify the broken calendar item and whether it is on the device or on the server.
Last edit: LiverpoolFCfan 2024-05-22
Thanks, I've solved my time zone problem!
One last thing (I hope...), it seems that some changes don't filter down to the devices. Here's what I can see in a loop in the logs for some accounts (several times a second) :
It tells me there are 8 changes in a calendar folder (FL1-10). When I enable debug logs for the account, here what I have :
Basically, if I understand well, it tells me there are changes because the version of the calendar stored on the server is "Calendrier de Pharmacie-1-1587055-1476-0-1587618-1674546" and on the client it is " Calendrier de Pharmacie-1-1587055-1476-0-1587618-1674546". But these two names are strictly equal. So I don't understand why Z-Push thinks there are changes, and if there are, why they're not being pushed correctly to the client.
On the other hand, when I create an event in webmail, it goes down to the devices in the account concerned.
I've tried the resync, fixstates and clearloop commands, and even a device reconfiguration, unfortunately without success.
I was able to identify the 8 events concerned using the LOGLEVEL_DEVICEID parameter. I can find them in the webmail (they date back to 2023). However, even if I delete them from the webmail, Z-Push still indicates that 8 changes are pending. This operation does have the effect of deleting them from the device.
After some research, I realise that the event deleted in this way does disappear from the 8 pending changes, but is replaced by a different one. In fact, the 8 pending events are constantly changing, but there are always 8 of them.
20MB of logs are generated every quarter of an hour because of this (plus the traffic and battery usage), and I really don't understand why...
That logging is not at DEVICEID level - it looks like it is at DEBUG level.
Unless you go to at least WBXML level you will not see it data going to/from the server.
I recommend DEVICEID when you are troubleshooting.
define('LOGUSERLEVEL', LOGLEVEL_DEVICEID);
Then, force a resync of the calendar for the user/device
/usr/share/...../z-push-admin.php -a resync -t calendar -u userORemail -d deviceID
Resync of N folders of type 'calendar' on device 'deviceID' of user 'userORemail': Requested
Once you see this, send an email to the account, or read one if you have access to it - anything to trigger a sync, and the calendar folders will be re-scanned, and the cache rebuilt, and the appointments will start to sync.
You can look at the log for the problem appointment(s)
Yes - I used DEBUG in the first place, then DEVICEID in order to see WBXML requests and responses and identify the events.
I tried to re-sync calendar folders and even delete the account from the device and add it again, without success.
For now, I disabled the faulty calendar by adding a "-" after its name from Zimbra webmail. I will dig again into DEVICEID log level in order to debug, but I think the best way to solve the issue is to delete the calendar and create it again (or delete all events older than a given date - maybe I will get rid of all faulty events).
Will keep this ticket up to date ; thanks again for all the precious information!
This is getting really strange... The problem now occurs randomly for all accounts, all devices and all folders (but only calendar folders). The only way to stop it is to run a resync from the Z-Push server, but the calm only lasts for an hour or so before it starts to storm again. I even tried a ‘z-push-admin -a resync -t calendar’ (to resynchronise ALL the calendars for all the accounts, and on all the devices), to no avail.
I have enabled WBXMLSTACK level logs for one of the accounts (mine) when the problem occurs. This generated a 15MB .log in about ten seconds. Going through it, here's what I can find:
So... changes or not ? According to z-push, there are changes, because it tries in loop to sync with the device. According to me, there aren't, because I haven't made any change to my calendar.
In any case, Z-Push doesn't seem to be sending much to the device, because when I search for ‘[WBXML] O’ in the logs, the only requests I find are pings...
Oh... what does this line tell me ? It is printing all around the logs, and only for the 'f10' folder... the one I have troubles with.
What does this status 2 mean ? Clearloop command from z-push-admin is'nt helping...
It is really difficult to help without seeing a full log to understand what is happening.
That said, a Ping Status of 2 means something occurred on the server that flagged as a change, The 2 is to tell the client to stop the Ping loop, ad issue a Sync to pick up the change.
Do you have any external process that is constantly re-syncing calendar appts to your calendar? They could look to the user as though there is nothing changing but the modification flags could be getting triggered
Sure, I understand. I attached a sample of the logs with the highest verbosity level. This is what I get in loop.
Thanks for this information. No, I don't have anything like that. I've been using z-push with the Zimbra backend for years without this kind of problem.
I tried to extract the HTTPS traffic between Outlook and the server and try to analyse it with Wireshark, thinking that all I had to do was integrate the server's private key into the software to decrypt the traffic, but it's actually more complicated than that...
If you set
define('ZIMBRA_DEBUG','username');in the zimbra config.php, and have DEBUG/DEVICEID level logging for that user in the specialLogUsers array, all the requests/responses from z-push to zimbra will be logged. Requests are in XML format, responses are in JSON.
Use a text editor with JSON formatting (like Notepad++ with the JSON plugin) and select or copy/paste just the response JSON for the user, and Format the JSON for reading.
Look for the notifications block sent back from the serveer. That might tell you what is changing on the server side.
I will take a look at your text file
Out of curiosity, did you define a specific value for this setting, or leave it at default?
// define('ZIMBRA_SYNC_WINDOW_DAYS', 366);
Apologies for this late reply, I tried to figure out what is happening by myself.
Here is what I found in the JSON replies :
- This is a loop of 4 responses: one with the context ‘refresh’, then 3 with the context ‘change’
- Every 4 JSON responses (so at every 'refresh' response), the session ID increases by 3
- The 'token' (change token) value is everytime the same
According to information I found here : https://gist.github.com/be1/562195/0c7f6b3e065b5a7db432c46f9ae9d73f231185df, this means there are no changes to push, because 'token' value does not change.
No, I left the 'ZIMBRA_SYNC_WINDOW_DAYS' option commented.
I'll continue to investigate and keep this ticket updated
If the sessionID is changing, have you read this in the INSTALL, and updated the limit accordingly?
Yes, I think the limit is high enough :
Additionally, mailbox.log doesn't state there are too many SOAP sessions :
The limit is per logged-in user - so you shouldn't need more that 7-8 unless you have a lot of devices sysning to the same account
Look for a PM from me.
Also, I note that you are using :8443 - Do you have the zimbra proxy installed? Usually you should have the NGINX proxy installed in front of the jetty web server.
Are your connections hitting the jetty server directly or going through the proxy?
I had the exact same problem. Randomly failed to sync calendar and server CPU usage with network traffic. Only a forced resync fixed the problem for a few hours. My problem was in z-push version 2.7.1. After reverting to version 2.6.4 everything was fine as before.