Following System Restart Trac Issues "Error: Unable to get database connection within 0 seconds" Message

[Thomas A. F. Thorne]

My Trac server is configured to automatically upgrade and reboot in the early ours of the morrning. This morning I found that it started sending me emails like this:

Error: Unable to get database connection within 0 seconds. (OperationalError: could not connect to server: Connection refused
 Is the server running on host "localhost" (::1) and accepting
 TCP/IP connections on port 5432?
could not connect to server: Connection refused
 Is the server running on host "localhost" (127.0.0.1) and accepting
 TCP/IP connections on port 5432?
)

These were triggered by an hourly cron job that tries to synchronize changes from a git repository.
 The command used is `/usr/local/bin/trac-admin /srv/trac/projects/gittrac/ repository sync <repo_name> | /usr/bin/logger -t trac-admin_sync`

Further to this the syslog shows the following error message:
May 30 02:25:06 trac Trac[main] ERROR: Internal Server Error: <RequestWithSession "GET ''">, referrer None#012Traceback (most recent call last):#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 554, in _dispatch_request#012 dispatcher.dispatch(req)#012 File "/usr/local/lib/python2.7/dist-packages/trac/web/main.py", line 247, in dispatch#012 resp = chosen_handler.process_request(req)#012 File "/usr/local/lib/python2.7/dist-packages/trac/wiki/web_ui.py", line 131, in process_request#012 page = WikiPage(self.env, pagename)#012 File "/usr/local/lib/python2.7/dist-packages/trac/wiki/model.py", line 49, in __init__#012 self._fetch(name, version, db)#012 File "/usr/local/lib/python2.7/dist-packages/trac/wiki/model.py", line 68, in _fetch#012 self.env.db_query(sql, args):#012 File "/usr/local/lib/python2.7/dist-packages/trac/db/api.py", line 124, in execute#012 return db.execute(query, params)#012 File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 128, in execute#012 cursor.execute(query, params if params is not None else [])#012 File "/usr/local/lib/python2.7/dist-packages/trac/db/util.py", line 72, in execute#012 return self.cursor.execute(sql_escape_percent(sql), args)#012OperationalError: terminating connection due to administrator command#012server closed the connection unexpectedly#012#011This probably means the server terminated abnormally#012#011before or while processing the request.#012OperationalError: terminating connection due to administrator command#012server closed the connection unexpectedly#012#011This probably means the server terminated abnormally#012#011before or while processing the request.
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor HudsonTracPlugin
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor RPCWeb
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor QueryModule
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor TicketModule
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor SearchModule
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor TicketStatsPlugin
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor AdminModule
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor ReportModule
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor RoadmapModule
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor TimelineModule
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor WikiModule
May 30 02:25:06 trac Trac[chrome] WARNING: Error with navigation contributor PDashboard
May 30 02:25:08 trac Trac[chrome] ERROR: Error during check of EMAIL_VIEW: TimeoutError: Unable to get database connection within 0 seconds. (OperationalError: could not connect to server: Connection refused#012#011Is the server running on host "localhost" (::1) and accepting#012#011TCP/IP connections on port 5432?#012could not connect to server: Connection refused#012#011Is the server running on host "localhost" (127.0.0.1) and accepting#012#011TCP/IP connections on port 5432?#012)
May 30 02:25:08 trac Trac[chrome] ERROR: Error during check of EMAIL_VIEW: TimeoutError: Unable to get database connection within 0 seconds. (OperationalError: could not connect to server: Connection refused#012#011Is the server running on host "localhost" (::1) and accepting#012#011TCP/IP connections on port 5432?#012could not connect to server: Connection refused#012#011Is the server running on host "localhost" (127.0.0.1) and accepting#012#011TCP/IP connections on port 5432?#012)

The above looks very similar to what is presented as a Warning and Trac error when you try to visit the Trac webpage.

I have a feeling that I have seen this before. In the past it was restarting the database or Trac service that resolved the issue I think. Yes my notes from before say:
"There seems to be a postgresql.service and a [e-mail] and a [e-mail] service. The first one seems to have a happy status, the 9.5 one is active but has warnings about the database connection failing and says the "database system is starting up" the 9.3 one is failed. I'd guess it is trying to use the 9.3 cluster that pg_lsclusters tells me is down. I did sudo service postgresql@9.3-main start which brought both clusters online. Now Trac is happy"

It looks like I had attempted to make the work around more perminiant with:
sudo systemctl enable postgresql@9.3-main
Created symlink from /etc/systemd/system/multi-user.target.wants/[e-mail] to /lib/systemd/system/postgresql@.service.
That obviously did not work though.

$ sudo service postgresql status
● postgresql.service - PostgreSQL RDBMS
   Loaded: loaded (/lib/systemd/system/postgresql.service; disabled; vendor preset: enabled)
   Active: inactive (dead)

May 30 02:20:31 trac systemd[1]: Stopped PostgreSQL RDBMS.

$ sudo service postgresql@9.5-main status
● [e-mail] - PostgreSQL Cluster 9.5-main
   Loaded: loaded (/lib/systemd/system/postgresql@.service; enabled; vendor preset: enabled)
   Active: inactive (dead)

ProblemType: Bug
DistroRelease: Ubuntu 16.04
Package: trac (not installed)
ProcVersionSignature: Ubuntu 4.4.0-78.99-generic 4.4.62
Uname: Linux 4.4.0-78-generic x86_64
ApportVersion: 2.20.1-0ubuntu2.6
Architecture: amd64
Date: Tue May 30 08:18:10 2017
InstallationDate: Installed on 2015-12-14 (532 days ago)
InstallationMedia: Ubuntu-Server 14.04.3 LTS "Trusty Tahr" - Beta amd64 (20150805)
ProcEnviron:
 LANGUAGE=en_GB:en
 TERM=xterm-256color
 PATH=(custom, no user)
 LANG=en_GB.UTF-8
 SHELL=/bin/bash
SourcePackage: trac
UpgradeStatus: Upgraded to xenial on 2016-10-25 (216 days ago)

[Thomas A. F. Thorne (tafthorne)]

To resolve the issue all I needed to do was:
$ sudo service postgresql start

I guess there is something in the sequencing of service start going wrong. I will try and look into it more later. I am not sure how Trac is packaged, how this server is setup and as a result how much of all this is a roll-your-own. I only raised this bug to keep track on things if this had all come out of a package upgrade in an odd way.