View Issue Details

IDProjectCategoryView StatusLast Update
0005902SOGoBackend Generalpublic2023-11-30 19:47
Reporterbcnx Assigned Tosebastien  
PrioritynormalSeverityblockReproducibilityalways
Status resolvedResolutionfixed 
Platform[Server] LinuxOSUbuntuOS Version16.04 LTS
Product Version5.8.0 
Fixed in Version5.9.1 
Summary0005902: 501 error after a short while
Description

Hi,

I installed SOGo by means of the packages in Debian 12. I used MariaDB (MySQL) as the backend. After a while I get an 501 error and this in the log file:

2023-11-18 14:34:47.939 sogod[325593:325593] EXCEPTION: <NSException: 0x559f0f4b24a0> NAME:NSInvalidArgumentException REASON:NSDataMalloc(instance) does not recognize isJSONString INFO:(null)
Nov 18 14:34:47 sogod [325593]: 81.244.215.185 "POST /SOGo/so/info/Mail/0/folderSent/view HTTP/1.1" 501 0/48 0.022 - - 0 - 14

This is temporarily fixed by deleting the user row in sogo_user_profile.

Why is this happening and how can I fix it?

Steps To Reproduce

Logging in, clicking on some mails and then receiving a 501 error. Removing the user row in sogo_user_profile, reload web UI and getting 501 again after a while.

TagsNo tags attached.

Activities

qhivert

qhivert

2023-11-22 15:08

administrator   ~0017452

Hello,

Could you follow the guideline here to use gdb and give us the backtrace -> https://www.sogo.nu/support/faq/how-do-i-debug-sogo.html

bcnx

bcnx

2023-11-22 19:27

reporter   ~0017453

I adapted the instructions for Debian Bookworm, but this command fails:

apt-get install libgnustep-base-dbg sogo-dbg sope4.9-dbg gdb

sogo-dbg is not available, neither are the other packages, except gdb,

thanks,

BC

qhivert

qhivert

2023-11-23 08:05

administrator   ~0017454

Last edited: 2023-11-23 09:29

Sorry I didn't see you use debian package instead of sogo one. I strongly suggest you to do so by adding this file in your source:

sudo tee /etc/apt/sources.list.d/SOGo.list &lt;&lt;EOF
deb https://packages.sogo.nu/nightly/5/debian/ bookworm bookworm
EOF

After that, see if the bug's still here. If yes, you will find sogo-dbg in our repo

quentin@quentin:~$ apt-cache policy sogo-dbg
sogo-dbg:
  Installed: (none)
  Candidate: 5.9.0.20231122-1
  Version table:
     5.9.0.20231122-1 500
        500 https://packages.sogo.nu/nightly/5/debian bookworm/bookworm amd64 Packages
bcnx

bcnx

2023-11-23 18:06

reporter   ~0017456

done, but the repository does not seem to be correctly signed:

W: GPG error: https://packages.sogo.nu/nightly/5/debian bookworm InRelease: The following signatures couldn't be verified because the public key is not available: NO_PUBKEY F8A27B36A6E2EAE9
E: The repository 'https://packages.sogo.nu/nightly/5/debian bookworm InRelease' is not signed.
N: Updating from such a repository can't be done securely, and is therefore disabled by default.
N: See apt-secure(8) manpage for repository creation and user configuration details.

qhivert

qhivert

2023-11-24 07:45

administrator   ~0017457

Last edited: 2023-11-24 07:46

Yes sorry, there are all commands needed here https://www.sogo.nu/download.html
To add the key in debian you'll need to

sudo wget -O- 'https://keys.openpgp.org/vks/v1/by-fingerprint/74FFC6D72B925A34B5D356BDF8A27B36A6E2EAE9' | sudo gpg --dearmor | sudo apt-key add -
bcnx

bcnx

2023-11-24 14:06

reporter   ~0017458

Hi,

I added they key with your command, but "apt update" still produces the same error:

W: GPG error: https://packages.sogo.nu/nightly/5/debian bookworm InRelease: The following signatures couldn't be verified because the public key is not available: NO_PUBKEY F8A27B36A6E2EAE9
E: The repository 'https://packages.sogo.nu/nightly/5/debian bookworm InRelease' is not signed.
N: Updating from such a repository can't be done securely, and is therefore disabled by default.
N: See apt-secure(8) manpage for repository creation and user configuration details.

qhivert

qhivert

2023-11-24 14:26

administrator   ~0017459

Last edited: 2023-11-24 14:36

I've just tried it on a fresh debian bookworm vm

quentin@quentin:~$ sudo tee /etc/apt/sources.list.d/SOGo.list <<EOF
deb https://packages.sogo.nu/nightly/5/debian/ bookworm bookworm
EOF

deb https://packages.sogo.nu/nightly/5/debian/ bookworm bookworm

quentin@quentin:~$ sudo apt update

Hit:1 http://security.debian.org/debian-security bookworm-security InRelease
Hit:2 http://deb.debian.org/debian bookworm InRelease
Hit:3 http://deb.debian.org/debian bookworm-updates InRelease
Get:4 https://packages.sogo.nu/nightly/5/debian bookworm InRelease [3,170 B]
Err:4 https://packages.sogo.nu/nightly/5/debian bookworm InRelease
The following signatures couldn't be verified because the public key is not available: NO_PUBKEY F8A27B36A6E2EAE9
Reading package lists... Done
W: GPG error: https://packages.sogo.nu/nightly/5/debian bookworm InRelease: The following signatures couldn't be verified because the public key is not available: NO_PUBKEY F8A27B36A6E2EAE9
E: The repository 'https://packages.sogo.nu/nightly/5/debian bookworm InRelease' is not signed.
N: Updating from such a repository can't be done securely, and is therefore disabled by default.
N: See apt-secure(8) manpage for repository creation and user configuration details.

quentin@quentin:~$ sudo wget -O- 'https://keys.openpgp.org/vks/v1/by-fingerprint/74FFC6D72B925A34B5D356BDF8A27B36A6E2EAE9' | sudo gpg --dearmor | sudo apt-key add -

Redirecting output to ‘wget-log’.
Warning: apt-key is deprecated. Manage keyring files in trusted.gpg.d instead (see apt-key(8)).
OK

quentin@quentin:~$ sudo apt update

Hit:1 http://security.debian.org/debian-security bookworm-security InRelease
Get:2 https://packages.sogo.nu/nightly/5/debian bookworm InRelease [3,170 B]
Get:3 https://packages.sogo.nu/nightly/5/debian bookworm/bookworm amd64 Packages [7,539 B]
Hit:4 http://deb.debian.org/debian bookworm InRelease
Hit:5 http://deb.debian.org/debian bookworm-updates InRelease
Fetched 10.7 kB in 5s (2,028 B/s)
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
188 packages can be upgraded. Run 'apt list --upgradable' to see them.
W: https://packages.sogo.nu/nightly/5/debian/dists/bookworm/InRelease: Key is stored in legacy trusted.gpg keyring (/etc/apt/trusted.gpg), see the DEPRECATION section in apt-key(8) for details.

quentin@quentin:~$ sudo apt install sogo

Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
The following additional packages will be installed:
apache2 apache2-data apache2-utils autotools-dev gnustep-base-common gnustep-base-runtime gnustep-common gnustep-make gobjc gobjc-12 libgnustep-base1.28 libhashkit2 liblasso3 libmariadb3 libmemcached11
liboath0 libobjc-12-dev libobjc4 libsbjson2.3 libsope-appserver4.9 libsope-core4.9 libsope-gdl1-4.9 libsope-ldap4.9 libsope-mime4.9 libsope-xml4.9 libxmlsec1-openssl libzip4 mariadb-common memcached
mysql-common sope4.9-gdl1-mysql sope4.9-libxmlsaxdriver
Suggested packages:
apache2-doc apache2-suexec-pristine | apache2-suexec-custom gnustep-make-doc gobjc-multilib gobjc-12-multilib gcc-12-doc libanyevent-perl libcache-memcached-perl libmemcached libterm-readkey-perl
libyaml-perl mysql-server
The following NEW packages will be installed:
apache2 apache2-data apache2-utils autotools-dev gnustep-base-common gnustep-base-runtime gnustep-common gnustep-make gobjc gobjc-12 libgnustep-base1.28 libhashkit2 liblasso3 libmariadb3 libmemcached11
liboath0 libobjc-12-dev libobjc4 libsbjson2.3 libsope-appserver4.9 libsope-core4.9 libsope-gdl1-4.9 libsope-ldap4.9 libsope-mime4.9 libsope-xml4.9 libxmlsec1-openssl libzip4 mariadb-common memcached
mysql-common sogo sope4.9-gdl1-mysql sope4.9-libxmlsaxdriver
0 upgraded, 33 newly installed, 0 to remove and 188 not upgraded.
Need to get 43.3 MB of archives.
After this operation, 117 MB of additional disk space will be used.
Do you want to continue? [Y/n]

bcnx

bcnx

2023-11-24 14:51

reporter   ~0017460

Hi,

cheers. I added "deb https://packages.sogo.nu/nightly/5/debian/ bookworm bookworm" manually to sources.list before. Now I used your "tee" command which put the repo in the sources.list.d subdir and now I can upgrade to the latest Sogo version. I do get errors however, but that's because of conflicts I think:

dpkg: error processing archive /tmp/apt-dpkg-install-m4ZcqS/40-libsope-xml4.9_4.9.r1664.20231124_amd64.deb (--unpack):
trying to overwrite '/usr/lib/libDOM.so.4.9.24', which is also in package libsope1 5.8.0-1
dpkg-deb: error: paste subprocess was killed by signal (Broken pipe)

So I will uninstall those packages first now,

BC

bcnx

bcnx

2023-11-24 15:01

reporter   ~0017461

OK, I installed everything succesfully now. Should I run the /usr/share/doc/sogo/sql-update-5.8.4_to_5.9.0.sh script now first? I was on 5.8.0 before upgrading ...

Cheers,

BC

bcnx

bcnx

2023-11-24 15:05

reporter   ~0017462

Hi,

so for the meantime I did a test and I could not login (Unhandled error response). This pops up in my sogo.log:

Nov 24 16:03:15 sogod [504130]: SOGoRootPage successful login from '81.82.219.243' for user 'info' - expire = -1 grace = -1
2023-11-24 16:03:15.614 sogod[504130:504130] EXCEPTION: <NSException: 0x5643929df510> NAME:NSInvalidArgumentException REASON:NSDataMalloc(instance) does not recognize isJSONString INFO:(null)

BC

qhivert

qhivert

2023-11-24 15:15

administrator   ~0017463

Last edited: 2023-11-24 15:16

Well now you can do two things:

  • add the folowing to your sogo.conf, it will print more logs
    SoObjectMethodDispatcherDebugEnabled = YES;
    SOGoDebugRequests = YES;
    ImapDebugEnabled = YES;
    LDAPDebugEnabled = YES;
    PGDebugEnabled = YES;
    SMTPDebugEnabled = YES;
    MySQL4DebugEnabled = YES;
    SOGoUIxDebugEnabled = YES;
    SOGoEASDebugEnabled = YES;
    WEResourceManagerDebugEnabled = YES;
    WODebugHTTPConnection = YES;

  • try the gdb to get the backtrace.

For your error I assume sogo try to read something from database that is supposed to be a json but isn't.

bcnx

bcnx

2023-11-24 16:53

reporter   ~0017464

I added the debug stuff and now I have in the log file:

Nov 24 17:50:57 sogod [506429]: 81.82.219.243 "GET /SOGo/login?language=English HTTP/1.1" 200 9382/0 0.023 38104 75% 432K - 12
Nov 24 17:51:03 sogod [506429]: |SOGo| starting method 'POST' on uri '/SOGo/so/passwordRecoveryEnabled'
Nov 24 17:51:03 sogod [506429]: |SOGo| request took 0.000436 seconds to execute
Nov 24 17:51:03 sogod [506429]: 81.82.219.243 "POST /SOGo/so/passwordRecoveryEnabled HTTP/1.1" 403 0/33 0.001 - - 0 - 12
Nov 24 17:51:04 sogod [506429]: |SOGo| starting method 'POST' on uri '/SOGo/so/passwordRecoveryEnabled'
Nov 24 17:51:04 sogod [506429]: |SOGo| request took 0.000489 seconds to execute
Nov 24 17:51:04 sogod [506429]: 81.82.219.243 "POST /SOGo/so/passwordRecoveryEnabled HTTP/1.1" 403 0/33 0.001 - - 0 - 12
Nov 24 17:51:08 sogod [506429]: |SOGo| starting method 'POST' on uri '/SOGo/connect'
2023-11-24 17:51:08.537 sogod[506429:506429] <MySQL4Channel[0x0x55cf145d26c0] connection=0x0x55cf13fdd310> SQL: SELECT c_password FROM sogo_users WHERE c_uid = 'info';
2023-11-24 17:51:08.537 sogod[506429:506429] <MySQL4Channel[0x0x55cf145d26c0] connection=0x0x55cf13fdd310> query has results, entering fetch-mode.
Nov 24 17:51:08 sogod [506429]: SOGoRootPage successful login from '81.82.219.243' for user 'info' - expire = -1 grace = -1
2023-11-24 17:51:08.538 sogod[506429:506429] <MySQL4Channel[0x0x55cf145d26c0] connection=0x0x55cf13fdd310> SQL: SELECT * FROM sogo_users WHERE (c_uid = 'info') OR (mail = 'info');
2023-11-24 17:51:08.539 sogod[506429:506429] <MySQL4Channel[0x0x55cf145d26c0] connection=0x0x55cf13fdd310> query has results, entering fetch-mode.
2023-11-24 17:51:08.539 sogod[506429:506429] MySQL4 connection established 0x0x55cf14661680
2023-11-24 17:51:08.539 sogod[506429:506429] ---------- -[MySQL4Channel openChannel]: <MySQL4Channel[0x0x55cf1464d250] connection=0x0x55cf14661680> opens channel count[1]
2023-11-24 17:51:08.539 sogod[506429:506429] MySQL4 channel 0x0x55cf1464d250 opened (connection=0x0x55cf14661680,sogo)
2023-11-24 17:51:08.539 sogod[506429:506429] <MySQL4Channel[0x0x55cf1464d250] connection=0x0x55cf14661680> SQL: SELECT c_defaults FROM sogo_user_profile WHERE c_uid = 'info';
2023-11-24 17:51:08.540 sogod[506429:506429] <MySQL4Channel[0x0x55cf1464d250] connection=0x0x55cf14661680> query has results, entering fetch-mode.
2023-11-24 17:51:08.542 sogod[506429:506429] EXCEPTION: <NSException: 0x55cf14694540> NAME:NSInvalidArgumentException REASON:NSDataMalloc(instance) does not recognize isJSONString INFO:(null)
Nov 24 17:51:08 sogod [506429]: |SOGo| request took 0.005575 seconds to execute
Nov 24 17:51:08 sogod [506429]: 81.82.219.243 "POST /SOGo/connect HTTP/1.1" 501 0/95 0.007 - - 264K - 13

bcnx

bcnx

2023-11-24 16:58

reporter   ~0017465

I deleted the SQL row for this user again and now things seem to work. I will test for a while and come back with feedback.

Thanks!

BC

bcnx

bcnx

2023-11-24 17:05

reporter   ~0017466

Searching mails produces a "Request failed" popup and does not seem to work. I cannot see anything in the log file related to that.

Cheers,

BC

bcnx

bcnx

2023-11-24 18:16

reporter   ~0017467

For the searches the Apache log does produce a 501 error, so there is still something wrong there ...

BC

bcnx

bcnx

2023-11-24 19:24

reporter   ~0017468

I have a 501 error again on the main page. log file:

2023-11-24 20:23:09.796 sogod[506429:506429] <MySQL4Channel[0x0x55cf1479c5c0] connection=0x0x55cf14a426c0> SQL: SELECT c_defaults FROM sogo_user_profile WHERE c_uid = 'info';
2023-11-24 20:23:09.796 sogod[506429:506429] <MySQL4Channel[0x0x55cf1479c5c0] connection=0x0x55cf14a426c0> query has results, entering fetch-mode.
2023-11-24 20:23:09.797 sogod[506429:506429] EXCEPTION: <NSException: 0x55cf14a53480> NAME:NSInvalidArgumentException REASON:NSDataMalloc(instance) does not recognize isJSONString INFO:(null)
Nov 24 20:23:09 sogod [506429]: |SOGo| request took 0.002805 seconds to execute
Nov 24 20:23:09 sogod [506429]: 81.82.219.243 "GET /SOGo/so/info/Mail/view HTTP/1.1" 501 0/0 0.004 - - 0 - 15

sebastien

sebastien

2023-11-27 15:00

administrator   ~0017470

Hi,

This is linked to table's collation :

Sebastien

bcnx

bcnx

2023-11-30 16:32

reporter   ~0017474

Hi,

thanks for reopening the issue.
The utf8mb4_0900_ai_ci collation seems not to be available in mariadb server.
I assume the nightly build needs to be compiled to be used?

Thanks,

BC

qhivert

qhivert

2023-11-30 16:34

administrator   ~0017475

Hello,
By nightly we called the new packages generated each day with the last developments. Simply use apt as usual.

bcnx

bcnx

2023-11-30 17:15

reporter   ~0017476

OK, I was able to do an upgrade with "apt upgrade", restarted sogo and now the 501 errors seem to be gone. Thanks for the assistance!

BC

Issue History

Date Modified Username Field Change
2023-11-22 14:45 bcnx New Issue
2023-11-22 15:08 qhivert Note Added: 0017452
2023-11-22 19:27 bcnx Note Added: 0017453
2023-11-23 08:05 qhivert Note Added: 0017454
2023-11-23 08:06 qhivert Note Edited: 0017454
2023-11-23 08:06 qhivert Note View State: 0017454: public
2023-11-23 08:06 qhivert Assigned To => qhivert
2023-11-23 08:06 qhivert Status new => feedback
2023-11-23 09:28 qhivert Note Edited: 0017454
2023-11-23 09:29 qhivert Note Edited: 0017454
2023-11-23 18:06 bcnx Note Added: 0017456
2023-11-23 18:06 bcnx Status feedback => assigned
2023-11-24 07:45 qhivert Note Added: 0017457
2023-11-24 07:45 qhivert Note Edited: 0017457
2023-11-24 07:45 qhivert Note Edited: 0017457
2023-11-24 07:46 qhivert Note Edited: 0017457
2023-11-24 07:46 qhivert Note View State: 0017457: public
2023-11-24 07:46 qhivert Status assigned => feedback
2023-11-24 14:06 bcnx Note Added: 0017458
2023-11-24 14:06 bcnx Status feedback => assigned
2023-11-24 14:26 qhivert Note Added: 0017459
2023-11-24 14:27 qhivert Note Edited: 0017459
2023-11-24 14:27 qhivert Note Edited: 0017459
2023-11-24 14:28 qhivert Note Edited: 0017459
2023-11-24 14:28 qhivert Note Edited: 0017459
2023-11-24 14:31 qhivert Note Edited: 0017459
2023-11-24 14:32 qhivert Note Edited: 0017459
2023-11-24 14:36 qhivert Note Edited: 0017459
2023-11-24 14:36 qhivert Note View State: 0017459: public
2023-11-24 14:37 qhivert Status assigned => feedback
2023-11-24 14:51 bcnx Note Added: 0017460
2023-11-24 14:51 bcnx Status feedback => assigned
2023-11-24 15:01 bcnx Note Added: 0017461
2023-11-24 15:05 bcnx Note Added: 0017462
2023-11-24 15:15 qhivert Note Added: 0017463
2023-11-24 15:16 qhivert Note Edited: 0017463
2023-11-24 15:16 qhivert Note View State: 0017463: public
2023-11-24 15:16 qhivert Status assigned => feedback
2023-11-24 16:53 bcnx Note Added: 0017464
2023-11-24 16:53 bcnx Status feedback => assigned
2023-11-24 16:58 bcnx Note Added: 0017465
2023-11-24 17:05 bcnx Note Added: 0017466
2023-11-24 18:16 bcnx Note Added: 0017467
2023-11-24 19:24 bcnx Note Added: 0017468
2023-11-27 15:00 sebastien Note Added: 0017470
2023-11-27 15:00 sebastien Assigned To qhivert => sebastien
2023-11-27 15:00 sebastien Status assigned => resolved
2023-11-27 15:00 sebastien Resolution open => fixed
2023-11-27 15:00 sebastien Fixed in Version => 5.9.1
2023-11-30 16:29 qhivert Status resolved => new
2023-11-30 16:29 qhivert Resolution fixed => reopened
2023-11-30 16:32 bcnx Note Added: 0017474
2023-11-30 16:34 qhivert Note Added: 0017475
2023-11-30 16:34 qhivert Status new => feedback
2023-11-30 17:15 bcnx Note Added: 0017476
2023-11-30 17:15 bcnx Status feedback => assigned
2023-11-30 19:47 sebastien Status assigned => resolved
2023-11-30 19:47 sebastien Resolution reopened => fixed