View Issue Details

IDProjectCategoryView StatusLast Update
0013528Tine 2.0Tinebasepublic2017-12-07 18:28
Reporterlab-at-nohlAssigned Topmehrer 
PrioritynormalSeveritycrashReproducibilityalways
Status closedResolutionfixed 
Product Version2017.08.6 Community Edition 
Target Version2017.08.10 Community EditionFixed in Version2017.08.10 Community Edition 
Summary0013528: Changing user account adds 8 MByte garbage to account field xprops, breaks some Admin functions and user cannot log in
DescriptionAs admin I changed a user account (new mail alias) which fails (although new alias is set). Edit window doesn't close.

Error displayed right after changing account settings:
===========================================

Fatal error: Uncaught PDOException: SQLSTATE[HY000]: General error: 2006 MySQL server has gone away in /var/www/vendor/zendframework/zendframework1/library/Zend/Db/Statement/Pdo.php:228
Stack trace:
#0 /var/www/vendor/zendframework/zendframework1/library/Zend/Db/Statement/Pdo.php(228): PDOStatement->execute(Array)
#1 /var/www/vendor/zendframework/zendframework1/library/Zend/Db/Statement.php(303): Zend_Db_Statement_Pdo->_execute(Array)
0000002 /var/www/vendor/zendframework/zendframework1/library/Zend/Db/Adapter/Abstract.php(480): Zend_Db_Statement->execute(Array)
#3 /var/www/vendor/zendframework/zendframework1/library/Zend/Db/Adapter/Pdo/Abstract.php(238): Zend_Db_Adapter_Abstract->query('SELECT DISTINCT...', Array)
0000004 /var/www/Tinebase/Acl/Roles.php(197): Zend_Db_Adapter_Pdo_Abstract->query(Object(Zend_Db_Select))
#5 /var/www/Tinebase/Model/User.php(263): Tinebase_Acl_Roles->getApplications('316aa8a2-6c19-1...', false)
#6 /var/www/Tinebase/Server/Abstract.php(149): Tinebase_Model_User->g in /var/www/tine/vendor/zendframework/zendframework1/library/Zend/Db/Statement/Pdo.php on line 235

User cannot log in anymore and its xprops field is full of \\\\\\.

DEBUG Log (short version):
======================

b192f a5c2c admin - 2017-10-06T17:52:07+00:00 DEBUG (7): Tinebase_Controller_Record_ModlogTrait::_writeModLog::71 Writing modlog for Tinebase_Model_FullUser
b192f a5c2c admin - 2017-10-06T17:52:08+00:00 WARN (4): Tinebase_Core::errorHandler::563 Error while sending QUERY packet. PID=25573 in /var/www/vendor/zendframework/zendframework1/library/Zend/Db/Statement/Pdo.php::228 (2)
b192f a5c2c admin - 2017-10-06T17:52:08+00:00 WARN (4): Tinebase_Core::errorHandler::564 #0 [internal function]: Tinebase_Core::errorHandler(2, 'Error while sen...', '/var/www/v...', 228, Array)
b192f a5c2c admin - 2017-10-06T17:52:08+00:00 DEBUG (7): Tinebase_Timemachine_ModificationLog::setModification::486SQLSTATE[HY000]: General error: 2006 MySQL server has gone away, query was: INSERT INTO `tine20_timemachine_modlog` (`change_type`, `application_id`, `record_id`, `record_type`, `record_backend`, `modification_time`, `modification_account`, `new_value`, `seq`, `client`, `id`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) Array
(
[change_type] => updated
[application_id] => 4d98d1a496971797938555321fe87a344d0742be
[record_id] => 31762cfe-6c19-1034-948d-17a0cca20f00
[record_type] => Tinebase_Model_FullUser
[record_backend] => Sql
[modification_time] => 2017-10-06 17:52:07
[modification_account] => 316aa8a2-6c19-1034-9484-17a0cca20f00
[new_value] => {"id":"31762cfe-6c19-1034-948d-17a0cca20f00","model":"Tinebase_Model_FullUser","diff":{"xprops":"{\"personalFSQuota\":0}"},"oldData":{"xprops":"\"\\\"\\\\\\\"\\\\\\\\\\\\\\\"<<<< repeat for 8 MByte >>>"\\\\\\\\\\\\\\\"\\\\\\\"\\\"\""}}
[seq] => 8
[client] => Tinebase_Server_Json - Mozilla/5.0 (Windows NT 6.3; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0
[id] => 25ab26d21a48ca58cc79c25556a05b276175fbc6
)

b192f a5c2c admin - 2017-10-06T17:52:08+00:00 ERR (3): Admin_Controller_User::update::253 PDOException: SQLSTATE[HY000]: General error: 2006 MySQL server has gone away in /var/www/vendor/zendframework/zendframework1/library/Zend/Db/Statement/Pdo.php:228
Stack trace: [...]

<<< Here are two SELECT statements regarding modlog following which can't be executed since MySQL dropped connection (died) >>>
Steps To ReproduceChange any field on user panel as Admin. User cannot login anymore.

Account's field xprops in DB is full with "\\\\" - set xprops to NULL manually make login possible again.
TagsNo tags attached.
mwticket

Activities

lab-at-nohl

lab-at-nohl

2017-10-09 14:26

developer   ~0020906

One additional note because I couldn't reproduce the error on my devel machine. The user in question (on my production server) has a unusual large storage quota and uses about 100 GByte. It may be related to that.
pmehrer

pmehrer

2017-10-12 18:00

developer   ~0020932

thank you for reporting this issue. Do you have maybe access to a database backup that contains the old xprops value before you did the record update?

Is the log still available? Could you look for the line at the beginning of the request?

44445 9c9e2 sclever - 2017-10-12T15:48:48+00:00 DEBUG (7): Tinebase_Server_Json::handle::159 is JSON request. rawdata: array (
  0 =>
  array (
    'jsonrpc' => '2.0',
    'method' => 'Admin.saveUser',
    'params' =>
    array (
      'recordData' => .... please DO NOT SEND THE DATA THAT FOLLOWS HERE

only xprops and the end of this array please. ... Probably this will just be
'xprops' => array (
          'personalFSQuota' => 0,
        ),
can you confirm that?
lab-at-nohl

lab-at-nohl

2017-10-13 14:41

developer   ~0020956

I can confirm that the log shows no other content in xprops array than what you wrote. After that only an empty array customfields follows. Nothing else.

What has been the content in table field xprops before I actually don't know. I propably have Backups (which I had to restore on an other machine unfortunately). According to my memory I would say it was "NULL" because all other users had (have) this... It will take some time...

Can I provide anything else in the meantime?
pmehrer

pmehrer

2017-10-16 06:31

developer   ~0020974

thank you for checking. I was not able to reproduce this. As the client send a proper value to the server, I am pretty sure that there was something corrupted in the database for that account. Guess we just have to wait for this to show up again. Did you try to alter that account record again? I would guess it works now just fine?
lab-at-nohl

lab-at-nohl

2017-10-22 00:45

developer   ~0021028

I can definitely reproduce this but it has random aspects. Because I had the feeling it may be related to the amount of data in Filemanager I took my own user and changed it (it has only some GBytes). I started by setting xprops in table tine20_accounts to NULL.

I added in Admin a alternate mail address, xprops became (the quotes are original): "\"\\\"\\\\\\\"\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"{\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"personalFSQuota\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\":0}\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\"\\\\\\\"\\\"\""

Later I changed nothing and just ok'ed the user unchanged, xprops became: {"personalFSQuota":0}

Next time I deleted the new mail alias, xprops became: "\"{\\\"personalFSQuota\\\":0}\""

Now I ok'ed the user with whom the problem originally occurred. Nothing changed but my own user changed its xprops to: "\"\\\"\\\\\\\"\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"{\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"personalFSQuota\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\":0}\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\"\\\\\\\"\\\"\""

Finally I set my user manually to: {"personalFSQuota":0} which to the other user resulted in: "\"\\\"\\\\\\\"\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"{\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"personalFSQuota\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\":0}\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"\\\\\\\\\\\\\\\"\\\\\\\"\\\"\""

At the last step I can't say for sure that there're inter-dependencies because it is the production system (maybe the other user's phone connected).

The other users haven't been changed recently they are still set to NULL and not affected.

=======================================

CONCLUSION:

xprops is set to (wrongly escaped?) garbage randomly (don't know why). It seems to be growing on every change of the user (in Admin or e.g. login). It may even affect other users (which do not have xprops set to NULL). The log is not showing an error.
pmehrer

pmehrer

2017-11-02 13:00

developer   ~0021064

tried to reproduce it again on a clean 2017.08.6 CE. It is not reproducable there. So it would be great if you could provide more information:

you said: "Later I changed nothing and just ok'ed the user unchanged, xprops became: {"personalFSQuota":0}" ... that tells me that the edit dialog sends sane data to the server. and that the issue occurs somewhere else. Can you verify that? Try to reproduce it and look in the logs for data send to the server? As written above:

44445 9c9e2 sclever - 2017-10-12T15:48:48+00:00 DEBUG (7): Tinebase_Server_Json::handle::159 is JSON request. rawdata: array (
  0 =>
  array (
    'jsonrpc' => '2.0',
    'method' => 'Admin.saveUser',
    'params' =>
    array (
      'recordData' => .... please DO NOT SEND THE DATA THAT FOLLOWS HERE

only xprops and the end of this array please. ... Probably this will just be
'xprops' => array (
          'personalFSQuota' => 0,
        ),
can you confirm that?

I even dont know yet if this is a FE problem in the JS doing a bad encoding and sending bad data to the server or if this happens somewhere on the server.
lab-at-nohl

lab-at-nohl

2017-11-12 03:18

developer   ~0021120

Thank you for your help. The error still persists. I can CONFIRM your assumption. It does not seem to be related to client side.

I wrote a Query-Log by Mysql, please see the changing statement yourself:

172 Query UPDATE `tine20_accounts` SET `login_name` = '%USER%', `expires_at` = NULL, `primary_group_id` = '%GROUP_ID%', `home_dir` = '/bin/false', `login_shell` = NULL, `openid` = NULL, `visibility` = 'displayed', `contact_id` = '%CONTACT_ID%', `display_name` = 'User, Name', `full_name` = 'Name User', `first_name` = 'Name', `last_name` = 'User', `email` = 'name@domain.tld', `last_modified_by` = '%SETUPUSER_ID%', `last_modified_time` = '2017-11-12 01:12:58', `seq` = '29', `xprops`
= '\"{\\\"personalFSQuota\\\":0}\"', `status` = 'enabled' WHERE (`id` = '%ACCOUNT_ID%')

The user account which has xprops is changed. After the change (!) `last_modified_by` = '%SETUPUSER_ID%'. Before it was the ID of my Administrator. So the culprit is setupuser!

Additionally I noticed that changes mostly occur in seconds 58 or 59 but always after one minute. The change must be initiate by any kind of automated process. Since I tried Tinebase.triggerAsyncEvents already I guess the source is ActionQueue (which is hard to log)...

I hope this helps.
lab-at-nohl

lab-at-nohl

2017-11-13 02:25

developer   ~0021122

One small update on this issue: The "garbage escape strings" in xprops are produced by json_encode when trying to encode an already json formatted string.

Hotfix for Tinebase/User/Sql.php (line 1073):
- } elseif (isset($accountData['xprops'])) {
+ } elseif (isset($accountData['xprops']) && !is_string($accountData['xprops'])) {

BUT: This patch is not sufficient and not a real fix. For any reason the Ldap-Sync for accounts is broken heavily. Some methods (DAV and ActiveSync at least, probably also some UI-calls) always trigger an updateUserInSqlBackend() on each request no matter if Ldap has really changed (which has definitely not).

Despite a lost of resources (caching?) this invokes a permanent change-process of the user in SQL. Whenever I change a user being "admin", after the next call of the user its last_modified_by will be changed to setupuser. This happened for all my active users. I doubt this behavior is related to xprops but I guess it came from new modeling setupuser.
pmehrer

pmehrer

2017-11-13 09:32

developer   ~0021124

thank you for the detailed analysis. We will fix the double encoding and look into the (presumably unnecessary) account updates in the sql backend. I'll let you know when there is an update on this topic.
pmehrer

pmehrer

2017-11-13 09:58

developer   ~0021126

Hotfix for Tinebase/User/Sql.php (line 1073):
- } elseif (isset($accountData['xprops'])) {
+ } elseif (isset($accountData['xprops']) && is_array($accountData['xprops'])) {

(your fix will work too, but because of Tinebase_Record_Abstract::xprops I would rather check for is_array, it is supposed to be an array) Will continue to look into avoiding unnecessary updates
pmehrer

pmehrer

2017-11-13 11:34

developer   ~0021128

regarding the often occuring updates:
in our own ldap installation I can not see this:
select last_modified_time from tine20_accounts order by last_modified_time DESC limit 20 \G
nothing unusual there.

Also \Tinebase_User::_syncDataAndUpdateUser makes some sort of diff comparison and only updates the sql backend if required. If you feel the updates are problematic, please look at the log and provide more information which code path the updates take.

thank you for your report again, it was very helpful (not to say essential) to fix the crucial double escaping bug!
lab-at-nohl

lab-at-nohl

2017-11-13 12:48

developer   ~0021130

1) Hotfix

I thought about checking for an array, too. But according to documentation, per default json_decode will return an object in most cases. Thus you also need to check for that, I guess. Therefore I decided to test vice versa, hence for a string...

Will you bring the fix to git?

2) I had a feeling that your Ldap behaves differently. Weird. I will follow up on this.

Regarding your Ldap: Are you sure that setupuser (which is default in pre-authentication phase instead of empty id since some releases) does not overwrite last_modified_by of an account? Although all users in my installation were created by admin by now all are last_modified_by setup user!

I will investigate \Tinebase_User::_syncDataAndUpdateUser further. Yesterday I thought it may be related to a missing property in Ldap (mine has no accountExpire). But I will come back to this issue.
pmehrer

pmehrer

2017-11-13 15:59

developer   ~0021134

"\Tinebase_User::_syncDataAndUpdateUser further. Yesterday I thought it may be related to a missing property in Ldap (mine has no accountExpire)." -> that sounds like a probable cause, if the accountExpire will be set to a value other than null again later either in the update code path or through an other process, the ldap sync will unset it again and again.
pmehrer

pmehrer

2017-11-14 03:55

developer   ~0021136

1) Hotfix:
is merged already https://gerrit.tine20.com/customers/#/c/6359/
json_decode in the tine20 context is always being called with $assoc = true parameter: json_decode($json, true) => it will always return an array.

Issue History

Date Modified Username Field Change
2017-10-06 21:28 lab-at-nohl New Issue
2017-10-09 08:28 pschuele Assigned To => pmehrer
2017-10-09 14:26 lab-at-nohl Note Added: 0020906
2017-10-12 18:00 pmehrer Note Added: 0020932
2017-10-13 14:41 lab-at-nohl Note Added: 0020956
2017-10-16 06:31 pmehrer Note Added: 0020974
2017-10-22 00:45 lab-at-nohl Note Added: 0021028
2017-11-02 13:00 pmehrer Note Added: 0021064
2017-11-12 03:18 lab-at-nohl Note Added: 0021120
2017-11-13 02:25 lab-at-nohl Note Added: 0021122
2017-11-13 09:32 pmehrer Note Added: 0021124
2017-11-13 09:58 pmehrer Note Added: 0021126
2017-11-13 11:34 pmehrer Note Added: 0021128
2017-11-13 12:48 lab-at-nohl Note Added: 0021130
2017-11-13 15:59 pmehrer Note Added: 0021134
2017-11-14 03:55 pmehrer Note Added: 0021136
2017-11-27 19:58 lab-at-nohl Status new => resolved
2017-11-27 19:58 lab-at-nohl Resolution open => fixed
2017-11-27 19:58 lab-at-nohl Fixed in Version => 2017.08.9 Community Edition
2017-11-27 19:58 lab-at-nohl Status resolved => closed
2017-12-07 18:28 pschuele Fixed in Version 2017.08.9 Community Edition => 2017.08.10 Community Edition
2017-12-07 18:28 pschuele Target Version => 2017.08.10 Community Edition