Bad server response 5.4.3

[Dominion]

Hello,
I've noticed the Bad server response error while trying search in Contacts. The same error I have in any part of system when trying search. The system is 5.4.3. I've tried to clear the cache, rebuild, etc. Logs shows nothing. Could somebody please help me with the issue?
Thanks!

[tanya]

Hi,
by what field are you filtered?
What is in espocrm log? (data/logs)

[Dominion]

Hello,
Just when I try to find a name in Contacts and click "Search".

[tanya]

What is in espocrm log? (data/logs)

[Dominion]

I look at /data/logs/espo-2018-10-08.log and see no log of such behavior. Only notes which are irrelevant to this case.

[2018-10-08 17:50:03] Espo.ERROR: Google Calendar Synchronization: Сергій Торчук could not connect to Google Server when synchronizing the calendar "ФОП в регистрации" [] []
[2018-10-08 17:50:03] Espo.ERROR: Google Calendar Synchronization: Сергій Торчук could not connect to Google Server when synchronizing the calendar "Подтверждение данных" [] []
[2018-10-08 17:50:03] Espo.ERROR: Google Calendar Synchronization: Сергій Торчук could not connect to Google Server when synchronizing the calendar "Main" [] []

[tanya]

click Search again and check log again. Also you can check server error log. The reason has been logged

[Dominion]

I've clicked several times and nothing in the data/logs, but, I find something in apache2 log - please see the txt file attached.

[tanya]

you attached access log, not error

[Dominion]

Sorry, it was newest file by date, I didn't pay enough attention to filename.
I've checked once more data/logs: there are daily log files there like espo-2018-10-09.log and nothing relevant inside. No new information after I click "search" several times with the error message.
e.g. the ending of espo-2018-10-09.log irrelevant to this error

[2018-10-09 17:10:02] Espo.ERROR: Google Calendar Synchronization: Сергій Торчук could not connect to Google Server when synchronizing the calendar "st@dominion.od.ua" [] []
[2018-10-09 17:10:02] Espo.ERROR: Google Calendar Synchronization: Сергій Торчук could not connect to Google Server when synchronizing the calendar "ФОП в регистрации" [] []
[2018-10-09 17:10:02] Espo.ERROR: Google Calendar Synchronization: Сергій Торчук could not connect to Google Server when synchronizing the calendar "Подтверждение данных" [] []
[2018-10-09 17:10:02] Espo.ERROR: Google Calendar Synchronization: Сергій Торчук could not connect to Google Server when synchronizing the calendar "Main" [] []

Also I've checked /var/log and /var/log/apache2 - error.log for current date contains two lines only

[Tue Oct 09 06:25:03.733379 2018] [mpm_prefork:notice] [pid 644] AH00163: Apache/2.4.10 (Debian) mpm-itk/2.4.7-02 configured -- resuming normal operations
[Tue Oct 09 06:25:03.733438 2018] [core:notice] [pid 644] AH00094: Command line: '/usr/sbin/apache2'

[tanya]

Check owner of espo-2018-10-09.log? Is it the same user, as server user?
Seams file is not writable for server user. It could happen only if cron is run by other user (maybe root), and log is not writable for server user

[Dominion]

no, the owner of all *.log files in /data/logs is root:root
I've changed data/config.php logger to DEBUG and got new lines in espo-2018-10-09.log after clicking search

[2018-10-09 17:41:02] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:42:02] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:43:03] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:44:02] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:45:02] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:46:03] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:47:02] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:48:03] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:49:03] Espo.DEBUG: BPM: processPendingFlows [] []
[2018-10-09 17:50:02] Espo.DEBUG: BPM: processPendingFlows [] []

[tanya]

change owner to server user:group (maybe www-data:www-data)

[Dominion]

aha! that was the case. Now it writes more info

[2018-10-09 18:34:15] Espo.ERROR: Uncaught Exception Error: "Call to undefined function Espo\Core\SelectManagers\mb_strpos()" at /var/www/                                                application/Espo/Core/SelectManagers/Base.php line 1729 {"exception":"[object] (Error(code: 0): Call to undefined function Espo\\Core\\Sel                                                ectManagers\\mb_strpos() at /var/www/application/Espo/Core/SelectManagers/Base.php:1729)"} []
[2018-10-09 18:34:15] Espo.ERROR: Uncaught Exception Error: "Call to undefined function Espo\Core\SelectManagers\mb_strpos()" at /var/www/                                                application/Espo/Core/SelectManagers/Base.php line 1729 {"exception":"[object] (Error(code: 0): Call to undefined function Espo\\Core\\Sel                                                ectManagers\\mb_strpos() at /var/www/application/Espo/Core/SelectManagers/Base.php:1729)"} []
[2018-10-09 18:34:15] Espo.ERROR: Uncaught Exception Error: "Call to undefined function Espo\Core\SelectManagers\mb_strpos()" at /var/www/                                                application/Espo/Core/SelectManagers/Base.php line 1729 {"exception":"[object] (Error(code: 0): Call to undefined function Espo\\Core\\Sel                                                ectManagers\\mb_strpos() at /var/www/application/Espo/Core/SelectManagers/Base.php:1729)"} []
[2018-10-09 18:34:16] Espo.ERROR: Uncaught Exception Error: "Call to undefined function Espo\Core\SelectManagers\mb_strpos()" at /var/www/                                                application/Espo/Core/SelectManagers/Base.php line 1729 {"exception":"[object] (Error(code: 0): Call to undefined function Espo\\Core\\Sel                                                ectManagers\\mb_strpos() at /var/www/application/Espo/Core/SelectManagers/Base.php:1729)"} []
[2018-10-09 18:34:16] Espo.ERROR: Uncaught Exception Error: "Call to undefined function Espo\Core\SelectManagers\mb_strpos()" at /var/www/                                                application/Espo/Core/SelectManagers/Base.php line 1729 {"exception":"[object] (Error(code: 0): Call to undefined function Espo\\Core\\Sel                                                ectManagers\\mb_strpos() at /var/www/application/Espo/Core/SelectManagers/Base.php:1729)"} []
[2018-10-09 18:34:16] Espo.ERROR: Uncaught Exception Error: "Call to undefined function Espo\Core\SelectManagers\mb_strpos()" at /var/www/                                                application/Espo/Core/SelectManagers/Base.php line 1729 {"exception":"[object] (Error(code: 0): Call to undefined function Espo\\Core\\Sel                                                ectManagers\\mb_strpos() at /var/www/application/Espo/Core/SelectManagers/Base.php:1729)"} []

[tanya]

install php mbstring extension

[Dominion]

install php mbstring extension

Done! And the problem is gone! Everything works perfectly now.
Thank you kindly