ACR v12 - Postgres service does not start

[mark05]

I ran into an issue recently where an ACR/Slave webpage was not responding. Restarting the ACR service did not help. Restarting the Postgres service ended up showing the "Service could not start" message. Finally after searching online a bit, I removed the postmaster.oid file and was able to start the service.

I will try to format and add more information whenever I get time.

-- UPDATE --
Server Profile:
Virtual Machine running Windows Server 2008 R2 and ACR v12 (cscm-12.0-1patch_12.0-sp0-0153) and PostgreSQL 8.0.7


Stuff I saw on the logs
#acr.log -- DB Goes down and brings ACR also down with it (PANIC!)

2015-10-05 19:42:40,736 [DBWatchDog thread] FATAL com.swhh.cs.d.q - DATABASE NOT RESPONSIVE. SHUTTING DOWN
2015-10-05 19:42:51,827 [pool-2-thread-2] WARN com.swhh.c.a.k - Thread DBWatchDog thread did not die in time

#postgresql-2015-10-05_152410.log -- DB Does not accept connections?

2015-10-05 19:28:50 LOG: could not fsync segment 0 of relation 1663/17253/29682334: Permission denied
2015-10-05 19:28:50 ERROR: storage sync failed on magnetic disk: Permission denied
2015-10-05 19:28:51 LOG: could not fsync segment 0 of relation 1663/17253/29682334: Permission denied
2015-10-05 19:28:51 ERROR: storage sync failed on magnetic disk: Permission denied
2015-10-05 19:39:00 LOG: could not rename "E:/Progra~1/Avaya/ContactRecorder/postgresql/data/pg_xlog/000000010000001100000088" to "E:/Progra~1/Avaya/ContactRecorder/postgresql/data/pg_xlog/000000010000001100000091", continuing to try
2015-10-05 19:43:38 LOG: could not receive data from client: No connection could be made because the target machine actively refused it.
2015-10-05 19:43:38 LOG: unexpected EOF on client connection

#postgresql-2015-10-04_163019.log -- Error starts at around 1am on Oct 4

2015-10-04 01:04:54 LOG: could not fsync segment 0 of relation 1663/17253/29682334: Permission denied
2015-10-04 01:04:54 ERROR: storage sync failed on magnetic disk: Permission denied
2015-10-04 01:04:55 LOG: could not fsync segment 0 of relation 1663/17253/29682334: Permission denied
2015-10-04 01:04:55 ERROR: storage sync failed on magnetic disk: Permission denied

#acr.log-2015-10-04 -- Notices that the 1AM Thread starts to run

2015-10-04 01:00:12,440 [1AM Thread] INFO com.swhh.cs.b.bm - Event raised alarms.logpurge [359479] [21392]
2015-10-04 01:00:12,721 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum analyze calls
2015-10-04 01:00:27,130 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum analyze calls took 14409 ms
2015-10-04 01:00:58,049 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum alarms
2015-10-04 01:00:58,236 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum alarms took 187 ms
2015-10-04 01:01:28,677 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum analyze parties
2015-10-04 01:02:16,006 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum analyze parties took 47329 ms
2015-10-04 01:02:46,339 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum analyze callsegments
2015-10-04 01:02:59,253 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum analyze callsegments took 12914 ms
2015-10-04 01:02:59,331 [1AM Thread] INFO com.swhh.cs.i.m - executing reindex table callsegments
2015-10-04 01:03:07,055 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. reindex table callsegments took 7724 ms
2015-10-04 01:03:37,290 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum analyze cssegments
2015-10-04 01:03:37,290 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum analyze cssegments took 0 ms
2015-10-04 01:04:07,627 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum analyze recordings
2015-10-04 01:04:18,928 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum analyze recordings took 11301 ms
2015-10-04 01:04:49,271 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum confighistory
2015-10-04 01:04:49,302 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum confighistory took 31 ms
2015-10-04 01:05:19,673 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum jobqueue
2015-10-04 01:05:23,433 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum jobqueue took 3760 ms
2015-10-04 01:05:53,801 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum udfs
2015-10-04 01:05:55,154 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum udfs took 1353 ms
2015-10-04 01:06:25,435 [1AM Thread] INFO com.swhh.cs.i.m - executing vacuum stnranges
2015-10-04 01:06:25,451 [1AM Thread] INFO com.swhh.cs.i.m - ...finished. vacuum stnranges took 16 ms
<< Content Truncated >>
2015-10-04 01:08:02,478 [1AM Thread] WARN com.swhh.csta.d.l - REFRESH: TSAPI service down.
2015-10-04 01:08:02,478 [1AM Thread] WARN com.swhh.csta.d.l - REFRESH: TSAPI service down.
2015-10-04 01:08:02,478 [1AM Thread] WARN com.swhh.csta.d.l - REFRESH: TSAPI service down.
2015-10-04 01:08:02,478 [1AM Thread] WARN com.swhh.csta.d.l - REFRESH: TSAPI service down.
2015-10-04 01:08:02,479 [1AM Thread] INFO com.swhh.cs.uarchive.s - Purging and checking for historic archive runs
2015-10-04 01:08:02,483 [1AM Thread] INFO com.swhh.cs.d.m - Daily House-keeping completed

My understanding:
ACR's 1AM Jobs starts to run which (maybe) caused DB to have some corruption or file rights issue. Online research shows possible AV issues but the this particular server did not have any.


Fun Fact: PostgreSQL 8.0 EOL date: October 2010
Source: http://www.postgresql.org/support/versioning/


Steps Taken:
1. Tried to restart ACR and DB services. DB Service does not start.
2. Remove postmaster.pid from E:\Progra~1\Avaya\ContactRecorder\postgresql\data
3. DB Services start fine and now ACR services also start.
4. Generate personal sigh of relief.
5. Verify application access and recording functionality.

[mark05]

Updates! October 14, 2015