Relationship Graph

View IssueDependency GraphShow Summary
Relationship Graph
related to related to child of child of duplicate of duplicate of

View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0004315SOGoWeb Preferencespublic2017-10-16 10:092018-03-13 11:42
Reporterfsoyer Assigned Toludovic  
PriorityurgentSeverityminorReproducibilityunable to reproduce
Status closedResolutionsuspended 
Platform[Server] LinuxOSRHEL/CentOSOS Version7
Summary0004315: User preferences disappear ramdomly
Description

Hi,
I open a new (critical) bug report regarding the preceding 0004260 because it is no longer correct for the reasons :

  • I must set impact to CRITICAL !!!
  • the problem isn't related to a server restart, nor to activesync as suspected before

So, one of my users loose all his preference this morning. This is not the first time since the report of 0004260, but before I had never had the information in time to search in sogo.log. This morning, the problem was detected between 9:30 and 10:30, so I could search.
The user lost all : signature, filters, preferences for mails or calendar. All is returned to default. Related informations follow.

Please help !!!

I have another question for that, to try to solve temporarily the problem :
I tried to extract the field c_settings for this user from a backup of mysql. I inserted in a temporary table, then update the field in sogo_user_profile for this user from the temporary table. It seems to be ok in mysql but in GUI the preferences of the user are not recovered (this is always the default values). What would be the correct procedure to recover his preferences from a backup ?

Steps To Reproduce

No idea how...

Additional Information

In sogo.log, between 9:30 and 10:30, I find this between two messages "...stringByTrimmingSpaces on NSNull !", hope this is revelant :

2017-10-16 10:18:13.752 sogod[16974] ERROR(-[NSNull(misc) forwardInvocation:]): called selector stringByTrimmingSpaces on NSNull !
2017-10-16 10:18:13.765 sogod[16974] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f7c24a3b6e0] connection=0x0x7f7c21f67878>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-16 10:18:13.765 sogod[16974] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f7c24a3b6e0] connection=0x0x7f7c21f67878>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-16 10:18:13.765 sogod[16974] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f7c24a3b6e0] connection=0x0x7f7c21f67878>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-16 10:18:13.765 sogod[16974] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f7c24a3b6e0] connection=0x0x7f7c21f67878>: got no value for column:
attribute=c_description

.....
15 or 20 others lines like above, then :
.....

Oct 16 10:18:13 sogod [16974]: [ERROR] <0x7f7c23272d70[SOGoAppointmentFolder]:personal> cyclic record doesn't have content -> {"c_category" = "<null>"; "c_classification" = 0; "c_component" = vevent; "c_creationdate" = 1497625315; "c_cycleinfo" = "{rules = (\"FREQ=YEARLY;COUNT=0;BYMONTH=9;BYDAY=MO;BYSETPOS=3\"); }"; "c_description" = "
"; "c_enddate" = 1505723400; "c_isallday" = 0; "c_iscycle" = 1; "c_isopaque" = 1; "c_lastmodified" = 1505722035; "c_location" = ""; "c_name" = "040000008200E00074C5B7101A82E0080000000040A5DC1C20B9D20100000000000000001000000062BD464319A0AA4BB9950CD6ABBCE16C.ics"; "c_nextalarm" = 1537170300; "c_orgmail" = ""; "c_participants" = "<null>"; "c_partmails" = "<null>"; "c_partstates" = ""; "c_priority" = 5; "c_sequence" = 0; "c_startdate" = 1505721600; "c_status" = 1; "c_uid" = 040000008200E00074C5B7101A82E0080000000040A5DC1C20B9D20100000000000000001000000062BD464319A0AA4BB9950CD6ABBCE16C; "c_version" = 2; }
Oct 16 10:18:13 sogod [16974]: [ERROR] <0x7f7c23272d70[SOGoAppointmentFolder]:personal> cyclic record doesn't have content -> {"c_category" = "<null>"; "c_classification" = 0; "c_component" = vevent; "c_creationdate" = 1497625313; "c_cycleinfo" = "{rules = (\"FREQ=YEARLY;COUNT=0;BYMONTH=8;BYMONTHDAY=28\"); }"; "c_description" = ""; "c_enddate" = 1503909000; "c_isallday" = 0; "c_iscycle" = 1; "c_isopaque" = 1; "c_lastmodified" = 1503906238; "c_location" = ""; "c_name" = "040000008200E00074C5B7101A82E008000000009092591C20B9D20100000000000000001000000019CC17FBBA0AD442969EE3871BFE89C8.ics"; "c_nextalarm" = 1503906300; "c_orgmail" = ""; "c_participants" = "<null>"; "c_partmails" = "<null>"; "c_partstates" = ""; "c_priority" = 5; "c_sequence" = 0; "c_startdate" = 1503907200; "c_status" = 1; "c_uid" = 040000008200E00074C5B7101A82E008000000009092591C20B9D20100000000000000001000000019CC17FBBA0AD442969EE3871BFE89C8; "c_version" = 7; }
Oct 16 10:18:13 sogod [16974]: [ERROR] <0x7f7c23272d70[SOGoAppointmentFolder]:personal> cyclic record doesn't have content -> {"c_category" = "<null>"; "c_classification" = 1; "c_component" = vevent; "c_creationdate" = 1505378278; "c_cycleinfo" = "{rules = (\"FREQ=WEEKLY;INTERVAL=2;BYDAY=FR\"); }"; "c_description" = ""; "c_enddate" = 1506038399; "c_isallday" = 1; "c_iscycle" = 1; "c_isopaque" = 0; "c_lastmodified" = 1505378278; "c_location" = ""; "c_name" = "0AA6928A3EA84A7EA9AA4023E0C3C93D0.ics"; "c_nextalarm" = 0; "c_orgmail" = ""; "c_participants" = "<null>"; "c_partmails" = "<null>"; "c_partstates" = ""; "c_priority" = 0; "c_sequence" = 0; "c_startdate" = 1505433600; "c_status" = 1; "c_uid" = 0AA6928A3EA84A7EA9AA4023E0C3C93D0; "c_version" = 0; }
Oct 16 10:18:13 sogod [16974]: [ERROR] <0x7f7c23272d70[SOGoAppointmentFolder]:personal> cyclic record doesn't have content -> {"c_category" = "<null>"; "c_classification" = 0; "c_component" = vevent; "c_creationdate" = 1505231954; "c_cycleinfo" = "{rules = (\"FREQ=WEEKLY;INTERVAL=2;BYDAY=TU\"); }"; "c_description" = ""; "c_enddate" = 1505234700; "c_isallday" = 0; "c_iscycle" = 1; "c_isopaque" = 1; "c_lastmodified" = 1508140694; "c_location" = ""; "c_name" = "C4E331072CA34E648A88FD0ABE9B91820.ics"; "c_nextalarm" = 1508861700; "c_orgmail" = ""; "c_participants" = "<null>"; "c_partmails" = "<null>"; "c_partstates" = ""; "c_priority" = 0; "c_sequence" = 0; "c_startdate" = 1505233800; "c_status" = 1; "c_uid" = C4E331072CA34E648A88FD0ABE9B91820; "c_version" = 2; }
Oct 16 10:18:13 sogod [16974]: [ERROR] >UIxCalListingActions> event '3A84-597EE880-F-5CCD7700.ics' has negative start: -3600 (skipped)

Oct 16 10:18:13 sogod [16974]: 127.0.0.1 "GET /SOGo/so/ceverine.clement@domain.com/Calendar/eventsblocks?ed=20171021&sd=20171015&view=weekview HTTP/1.1" 200 6320/0 0.080 - - 0
Oct 16 10:18:13 sogod [8236]: 127.0.0.1 "GET /SOGo/so/karine.fouquet@domain.com/Mail/0/folderINBOX/1714/view HTTP/1.1" 200 40178/0 0.986 - - 308K
Oct 16 10:18:13 sogod [31715]: 127.0.0.1 "GET /SOGo/so/ceverine.clement@domain.com/Calendar/eventslist?asc=1&day=20171016&filterpopup=view_next7&search=title_Category_Location&sort=title&value= HTTP/1.1" 200 5997/0 0.124 - - 0
2017-10-16 10:18:14.883 sogod[31715] ERROR(-[NSNull(misc) forwardInvocation:]): called selector stringByTrimmingSpaces on NSNull !

TagsNo tags attached.

Relationships

Relationship GraphDependency Graph
related to 0004260 resolvedludovic After a restart of services on servers, some user settings are resetted 

Activities

fsoyer

fsoyer

2017-10-16 10:12

reporter   ~0012381

The user concerned is karine.fouquet
fsoyer

fsoyer

2017-10-16 10:19

reporter   ~0012382

Last edited: 2017-10-16 10:54

[EDIT] : Well, after stopping sogo, I restored the table sogo_user_profile from the last backup of mysql (last night), and the preferences are ok. This is a workaround for now, but... please help !
fsoyer

fsoyer

2017-11-02 10:52

reporter   ~0012408

Hi,
a user forgot to tell us about the lost of his preferences last monday, around 13pm (the vacations were more important... :/ )
Luckily we keep 7 days of logs. Searching in it I find, again, this error "cyclic record doesn't have content..." at this time. We noticed no errors or latency on Mysql (exactly MariaDB 10) at this time, and no load on the server (cpu, memory...). And no restart of sogod (or server), possible reason that I suspected at the beginning.
What can be the reason of the "cyclic record" error ?

NOTE : I guess that it will be difficult to activate the debug mode. First, I can't restart sogo for now on this (prod) server. Second, it is a random error, we can't know when it will happen and we are afraid of a sogo.log filling the disk...

2017-10-30 13:03:43.565 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.566 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
Oct 30 13:03:43 sogod [27432]: [ERROR] >UIxCalListingActions> event '3A84-597EE880-F-5CCD7700.ics' has negative start: -3600 (skipped)
2017-10-30 13:03:43.574 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.574 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.575 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.575 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.575 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.575 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
2017-10-30 13:03:43.576 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_content
valueClass=NSString
type=TEXT
2017-10-30 13:03:43.576 sogod[27434] ERROR(-[MySQL4Channel primaryFetchAttributes:withZone:]): <MySQL4Channel[0x0x7f6bbfe99080] connection=0x0x7f6bbfc1f1c8>: got no value for column:
attribute=c_title
valueClass=NSString
type=VARCHAR
Oct 30 13:03:43 sogod [27434]: [ERROR] <0x7f6bbff8d7d0[SOGoAppointmentFolder]:personal> cyclic record doesn't have content -> {"c_category" = "<null>"; "c_classification" = 0; "c_component" = vevent; "c_creationdate" = 1497625315; "c_cycleinfo" = "{rules = (\"FREQ=YEARLY;COUNT=0;BYMONTH=9;BYDAY=MO;BYSETPOS=3\"); }"; "c_description" = "
"; "c_enddate" = 1505723400; "c_isallday" = 0; "c_iscycle" = 1; "c_isopaque" = 1; "c_lastmodified" = 1505722035; "c_location" = ""; "c_name" = "040000008200E00074C5B7101A82E0080000000040A5DC1C20B9D20100000000000000001000000062BD464319A0AA4BB9950CD6ABBCE16C.ics"; "c_nextalarm" = 1537170300; "c_orgmail" = ""; "c_participants" = "<null>"; "c_partmails" = "<null>"; "c_partstates" = ""; "c_priority" = 5; "c_sequence" = 0; "c_startdate" = 1505721600; "c_status" = 1; "c_uid" = 040000008200E00074C5B7101A82E0080000000040A5DC1C20B9D20100000000000000001000000062BD464319A0AA4BB9950CD6ABBCE16C; "c_version" = 2; }
Oct 30 13:03:43 sogod [27434]: [ERROR] <0x7f6bbff8d7d0[SOGoAppointmentFolder]:personal> cyclic record doesn't have content -> {"c_category" = "<null>"; "c_classification" = 0; "c_component" = vevent; "c_creationdate" = 1497625313; "c_cycleinfo" = "{rules = (\"FREQ=YEARLY;COUNT=0;BYMONTH=8;BYMONTHDAY=28\"); }"; "c_description" = ""; "c_enddate" = 1503909000; "c_isallday" = 0; "c_iscycle" = 1; "c_isopaque" = 1; "c_lastmodified" = 1503906238; "c_location" = ""; "c_name" = "040000008200E00074C5B7101A82E008000000009092591C20B9D20100000000000000001000000019CC17FBBA0AD442969EE3871BFE89C8.ics"; "c_nextalarm" = 1503906300; "c_orgmail" = ""; "c_participants" = "<null>"; "c_partmails" = "<null>"; "c_partstates" = ""; "c_priority" = 5; "c_sequence" = 0; "c_startdate" = 1503907200; "c_status" = 1; "c_uid" = 040000008200E00074C5B7101A82E008000000009092591C20B9D20100000000000000001000000019CC17FBBA0AD442969EE3871BFE89C8; "c_version" = 7; }
Oct 30 13:03:43 sogod [27434]: [ERROR] <0x7f6bbff8d7d0[SOGoAppointmentFolder]:personal> cyclic record doesn't have content -> {"c_category" = "<null>"; "c_classification" = 1; "c_component" = vevent; "c_creationdate" = 1505378278; "c_cycleinfo" = "{rules = (\"FREQ=WEEKLY;INTERVAL=2;BYDAY=FR\"); }"; "c_description" = ""; "c_enddate" = 1506038399; "c_isallday" = 1; "c_iscycle" = 1; "c_isopaque" = 0; "c_lastmodified" = 1505378278; "c_location" = ""; "c_name" = "0AA6928A3EA84A7EA9AA4023E0C3C93D0.ics"; "c_nextalarm" = 0; "c_orgmail" = ""; "c_participants" = "<null>"; "c_partmails" = "<null>"; "c_partstates" = ""; "c_priority" = 0; "c_sequence" = 0; "c_startdate" = 1505433600; "c_status" = 1; "c_uid" = 0AA6928A3EA84A7EA9AA4023E0C3C93D0; "c_version" = 0; }
Oct 30 13:03:43 sogod [27434]: [ERROR] <0x7f6bbff8d7d0[SOGoAppointmentFolder]:personal> cyclic record doesn't have content -> {"c_category" = "<null>"; "c_classification" = 0; "c_component" = vevent; "c_creationdate" = 1505231954; "c_cycleinfo" = "{rules = (\"FREQ=WEEKLY;INTERVAL=2;BYDAY=TU\"); }"; "c_description" = ""; "c_enddate" = 1505234700; "c_isallday" = 0; "c_iscycle" = 1; "c_isopaque" = 1; "c_lastmodified" = 1508860942; "c_location" = ""; "c_name" = "C4E331072CA34E648A88FD0ABE9B91820.ics"; "c_nextalarm" = 1510074900; "c_orgmail" = ""; "c_participants" = "<null>"; "c_partmails" = "<null>"; "c_partstates" = ""; "c_priority" = 0; "c_sequence" = 0; "c_startdate" = 1505233800; "c_status" = 1; "c_uid" = C4E331072CA34E648A88FD0ABE9B91820; "c_version" = 3; }
ludovic

ludovic

2018-03-12 17:39

administrator   ~0012656

Do you have 2 SOGo servers pointing to the same DB?
fsoyer

fsoyer

2018-03-13 11:40

reporter   ~0012672

Last edited: 2018-03-13 11:40

Hello Ludovic,
no, the server is alone, and the DB local on it. To be honest, the problem occurs twice in november and december, but no more since the new year... There was no upgrade on this sogo since november as I was waiting for more informations, and the service was restarted some times without lost of datas.
With this kind of random problem, hard to say what happened :(
I suggest to close this for the moment as I can't give more informations. I'll reopen a bug if necessary ?
ludovic

ludovic

2018-03-13 11:42

administrator   ~0012673

Suspending for now.

Issue History

Date Modified Username Field Change
2017-10-16 10:09 fsoyer New Issue
2017-10-16 10:12 fsoyer Note Added: 0012381
2017-10-16 10:19 fsoyer Note Added: 0012382
2017-10-16 10:53 fsoyer Note Edited: 0012382
2017-10-16 10:54 fsoyer Note Edited: 0012382
2017-10-17 09:50 Christian Mack Relationship added related to 0004260
2017-11-02 10:52 fsoyer Note Added: 0012408
2018-03-12 17:39 ludovic Note Added: 0012656
2018-03-12 17:39 ludovic Severity crash => minor
2018-03-13 11:40 fsoyer Note Added: 0012672
2018-03-13 11:40 fsoyer Note Edited: 0012672
2018-03-13 11:42 ludovic Note Added: 0012673
2018-03-13 11:42 ludovic Status new => closed
2018-03-13 11:42 ludovic Assigned To => ludovic
2018-03-13 11:42 ludovic Resolution open => suspended