1 Topic by Thierry (edited by Thierry 2017-01-04 12:40:32)

  • Thierry
  • Member
  • Offline
  • Registered: 2015-08-09
  • Posts: 180

Topic: *1 upstream prematurely closed connection while reading response ...

==== Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.5-1
- Linux/BSD distribution name and version: Debian 8
- Store mail accounts in which backend (LDAP/MySQL/PGSQL):  Mysql
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? No
- Related log if you're reporting an issue: /var/log/nginx/
====
Hi there,

I am using EFA in front  of my iRedmail server.
I had to reinstall my server (thx vmware) from 2015 version.
I have followed the procedure to upgrade the system to version  0.9.5-1.
Things are working well except when I try to connect to Sogo.

 [error] 21385#21385: *1 upstream prematurely closed connection while reading response header from upstream, client: **.**.**.**, server: 192.***.***.***, request: "GET /favicon.ico HTTP/2.0", upstream: "https://192.***.***.***:port_number/favicon.ico", host: "hostname:port_number", referrer: "https://hostname:port_number/SOGo/"
2017/01/04 06:12:38 [alert] 21385#21385: *2 open socket #17 left in connection 5
2017/01/04 06:12:38 [alert] 21385#21385: aborting

Any ideas ?
Thyx

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,059

Re: *1 upstream prematurely closed connection while reading response ...

The log is not clear at all, please check SOGo log file.

3 Reply by Thierry (edited by Thierry 2017-01-04 14:53:28)

  • Thierry
  • Member
  • Offline
  • Registered: 2015-08-09
  • Posts: 180

Re: *1 upstream prematurely closed connection while reading response ...

Seems to be a problem with Mysql:

2017-01-04 08:33:27.892 sogod[4113] ERROR: could not open MySQL4 connection to database 'sogo': Can't connect to MySQL server on '127.0.0.1' (111)
Jan 04 08:33:27 sogod [4113]: [ERROR] <0x0x7f902053f030[GCSChannelManager]> could not open channel <MySQL4Channel[0x0x7f90202b2710] connection=0x(null)> for mysql://127.0.0.1/sogo/sogo_user_profile
Jan 04 08:33:27 sogod [4113]: [WARN] <0x0x7f902053f030[GCSChannelManager]>   will prevent opening of this channel 5 seconds after 2017-01-04 08:33:27 +0200
2017-01-04 08:33:27.895 sogod[4111] ERROR: could not open MySQL4 connection to database 'sogo': Can't connect to MySQL server on '127.0.0.1' (111)
Jan 04 08:33:27 sogod [4111]: [ERROR] <0x0x7f902053f030[GCSChannelManager]> could not open channel <MySQL4Channel[0x0x7f90202b2710] connection=0x(null)> for mysql://127.0.0.1/sogo/sogo_user_profile
Jan 04 08:33:27 sogod [4111]: [WARN] <0x0x7f902053f030[GCSChannelManager]>   will prevent opening of this channel 5 seconds after 2017-01-04 08:33:27 +0200
mysql> USE sogo;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> show tables;
+-------------------------------+
| Tables_in_sogo                |
+-------------------------------+
| sogo_alarms_folder            |
| sogo_folder_info              |
| sogo_sessions_folder          |
| sogo_user_profile             |
| sogoevrimael0014d7d7d3d       |
| sogoevrimael0014d7d7d3d_acl   |
| sogoevrimael0014d7d7d3d_quick |
| sogolaurence0013c48fd35       |
| sogolaurence0013c48fd35_acl   |
| sogolaurence0013c48fd35_quick |
| sogolaurence0017d2efa28       |
| sogolaurence0017d2efa28_acl   |
| sogolaurence0017d2efa28_quick |
| sogolenaigst0012d54f77b       |
| sogolenaigst0012d54f77b_acl   |
| sogolenaigst0012d54f77b_quick |
| sogolenaigst00165422c9a       |
| sogolenaigst00165422c9a_acl   |
| sogolenaigst00165422c9a_quick |
| sogotstmaele00129a5988e       |
| sogotstmaele00129a5988e_acl   |
| sogotstmaele00129a5988e_quick |
| users                         |
+-------------------------------+
23 rows in set (0.00 sec)

4 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,059

Re: *1 upstream prematurely closed connection while reading response ...

Any related error in MySQL log file? Does it reach max connections? Does restarting sogo service help?

5 Reply by Thierry (edited by Thierry 2017-01-04 23:19:00)

  • Thierry
  • Member
  • Offline
  • Registered: 2015-08-09
  • Posts: 180

Re: *1 upstream prematurely closed connection while reading response ...

ZhangHuangbin wrote:

Any related error in MySQL log file? Does it reach max connections? Does restarting sogo service help?

After restarting Sogo:

 tail -f sogo.log
Jan 04 17:13:34 sogod [16959]: vmem size check enabled: shutting down app when vmem > 384 MB
Jan 04 17:13:34 sogod [16959]: <0x0x7f0938071810[SOGoProductLoader]> SOGo products loaded from '/usr/lib/GNUstep/SOGo':
Jan 04 17:13:34 sogod [16959]: <0x0x7f0938071810[SOGoProductLoader]>   ContactsUI.SOGo, Mailer.SOGo, SchedulerUI.SOGo, MailPartViewers.SOGo, ActiveSync.SOGo, MailerUI.SOGo, Contacts.SOGo, CommonUI.SOGo, MainUI.SOGo, PreferencesUI.SOGo, AdministrationUI.SOGo, Appointments.SOGo
Jan 04 17:13:34 sogod [16959]: <0x0x7f0937ec1000[WOWatchDog]> listening on 127.0.0.1:20000
Jan 04 17:13:34 sogod [16959]: <0x0x7f0937ec1000[WOWatchDog]> watchdog process pid: 16959
Jan 04 17:13:34 sogod [16959]: <0x0x7f0934b8edc0[WOWatchDogChild]> watchdog request timeout set to 10 minutes
Jan 04 17:13:34 sogod [16959]: <0x0x7f0937ec1000[WOWatchDog]> preparing 3 children
Jan 04 17:13:34 sogod [16959]: <0x0x7f0937ec1000[WOWatchDog]> child spawned with pid 16979
Jan 04 17:13:34 sogod [16959]: <0x0x7f0937ec1000[WOWatchDog]> child spawned with pid 16983
Jan 04 17:13:34 sogod [16959]: <0x0x7f0937ec1000[WOWatchDog]> child spawned with pid 16986

Mysql logs (after a restart):

tail  error.log
170104 16:16:54 InnoDB: Completed initialization of buffer pool
170104 16:16:54 InnoDB: highest supported file format is Barracuda.
170104 16:16:54  InnoDB: Waiting for the background threads to start
170104 16:16:55 InnoDB: 5.5.53 started; log sequence number 189605976
170104 16:16:55 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
170104 16:16:55 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
170104 16:16:55 [Note] Server socket created on IP: '127.0.0.1'.
170104 16:16:55 [Note] Event Scheduler: Loaded 0 events
170104 16:16:55 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.53-0+deb8u1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Debian)

Perhaps a  problem  after the upgrade of iredmail has been done ?

6 Reply by Thierry

  • Thierry
  • Member
  • Offline
  • Registered: 2015-08-09
  • Posts: 180

Re: *1 upstream prematurely closed connection while reading response ...

I am doing a local test.
I will use  the console browser: lynx.

When doing my "lynx https://server_hostanme.domain.ltd:444/SOGo/

With translation:

Recherche hostname.domain.ltd:444   - looking for ...
Connexion HTTPS à hostname.domain.ltd:444 - https connection to ...
Connection vérifiée à hostname.domain.ltd (sujet=hostname.domain.ltd) - Verified connection  ...
Certificat émis par: /C=FR/ST=Paris/L=Paris/O=Gandi/CN=Gandi Standard SSL CA 2 
Connection HTTP sécurisée 128-bit TLS1.2 (ECDHE_RSA_AES_128_GCM_SHA256) - connection  to HTTP secured ...
Envoi de la requête HTTP.  Sending HTTP request
Requête HTTP envoyée. Attente de réponse. - HTTP request has been send, waiting dor answer ...
Alerte! : Erreur de lecture inattendue ; connexion interrompue. Alerte,  Error unattented reading , connection closed ...
Accès impossible `https:/hostname.domain.ltd:444/' Impossible acces to ....
Alerte! : Impossible d'accéder au document - Alerte,  could  not access to the document ...

Thx

7 Reply by Thierry

  • Thierry
  • Member
  • Offline
  • Registered: 2015-08-09
  • Posts: 180

Re: *1 upstream prematurely closed connection while reading response ...

logs from the cron job "sogo-ealarms-notify" of this morning

2017-01-05 08:49:04.793 sogo-ealarms-notify[4129] ERROR: could not open MySQL4 connection to database 'sogo': Can't connect to MySQL server on '127.0.0.1' (111)
<0x0x19e8560[GCSChannelManager]> could not open channel <MySQL4Channel[0x0x183c600] connection=0x(null)> for mysql://127.0.0.1/sogo/sogo_alarms_folder
<0x0x19e8560[GCSChannelManager]>   will prevent opening of this channel 5 seconds after 2017-01-05 08:49:04 +0100
2017-01-05 08:49:04.565 sogo-tool[4127] ERROR: could not open MySQL4 connection to database 'sogo': Can't connect to MySQL server on '127.0.0.1' (111)
<0x0x192edf0[GCSChannelManager]> could not open channel <MySQL4Channel[0x0x17c5440] connection=0x(null)> for mysql://127.0.0.1/sogo/sogo_sessions_folder
<0x0x192edf0[GCSChannelManager]>   will prevent opening of this channel 5 seconds after 2017-01-05 08:49:04 +0100
2017-01-05 08:49:04.692 sogo-tool[4127] Can't aquire channel
2017-01-05 08:49:05.307 sogo-ealarms-notify[4165] ERROR: could not open MySQL4 connection to database 'sogo': Can't connect to MySQL server on '127.0.0.1' (111)
<0x0x14cc560[GCSChannelManager]> could not open channel <MySQL4Channel[0x0x1320600] connection=0x(null)> for mysql://127.0.0.1/sogo/sogo_alarms_folder
<0x0x14cc560[GCSChannelManager]>   will prevent opening of this channel 5 seconds after 2017-01-05 08:49:05 +0100

8 Reply by Thierry

  • Thierry
  • Member
  • Offline
  • Registered: 2015-08-09
  • Posts: 180

Re: *1 upstream prematurely closed connection while reading response ...

In the sogo.conf file, I have uncomment  the debug mode for  Sogo.

tail  sogo.log
2017-01-05 10:21:36.900 sogod[5609] MySQL4 connection established 0x0x7faafa5d2830
2017-01-05 10:21:36.901 sogod[5609] MySQL4 channel 0x0x7faafa8288b0 opened (connection=0x0x7faafa5d2830,sogo)
2017-01-05 10:21:36.901 sogod[5609] <MySQL4Channel[0x0x7faafa8288b0] connection=0x0x7faafa5d2830> SQL: SELECT count(*) FROM sogo_user_profile;
2017-01-05 10:21:36.902 sogod[5609] <MySQL4Channel[0x0x7faafa8288b0] connection=0x0x7faafa5d2830>   query has results, entering fetch-mode.
2017-01-05 10:21:36.902 sogod[5609] <MySQL4Channel[0x0x7faafa8288b0] connection=0x0x7faafa5d2830> SQL: SELECT count(*) FROM sogo_folder_info;
2017-01-05 10:21:36.902 sogod[5609] <MySQL4Channel[0x0x7faafa8288b0] connection=0x0x7faafa5d2830>   query has results, entering fetch-mode.
2017-01-05 10:21:36.904 sogod[5609] <MySQL4Channel[0x0x7faafa8288b0] connection=0x0x7faafa5d2830> SQL: SELECT count(*) FROM sogo_sessions_folder                                                   ;
2017-01-05 10:21:36.905 sogod[5609] <MySQL4Channel[0x0x7faafa8288b0] connection=0x0x7faafa5d2830>   query has results, entering fetch-mode.
2017-01-05 10:21:36.905 sogod[5609] <MySQL4Channel[0x0x7faafa8288b0] connection=0x0x7faafa5d2830> SQL: SELECT count(*) FROM sogo_alarms_folder;
2017-01-05 10:21:36.905 sogod[5609] <MySQL4Channel[0x0x7faafa8288b0] connection=0x0x7faafa5d2830>   query has results, entering fetch-mode.

Seems to connect to mysql  ....

9 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,059

Re: *1 upstream prematurely closed connection while reading response ...

Log files are fine.
MAYBE caused by not restarting mysql/sogo services after package upgraded.