expose open_port fails with no-op change

[Eric Snow]

Running "juju deploy postgresql" resulted in a service with an error state.[1] I'm using a local provider, so this may be related to https://bugs.launchpad.net/charms/+source/postgresql/+bug/993158. I'll include more detailed info momentarily.

[1] Incidentally, I could not remove the service. However, I'm handling that in a separate bug report: https://bugs.launchpad.net/juju-core/+bug/1359827

[Eric Snow (ericsnowcurrently)]

$ juju bootstrap # local
...
$ juju deploy postgresql
$ juju status
environment: local
machines:
  "0":
    agent-state: started
    agent-version: 1.21-alpha1.1
    dns-name: localhost
    instance-id: localhost
    series: trusty
    state-server-member-status: has-vote
  "1":
    agent-state: started
    agent-version: 1.21-alpha1.1
    dns-name: 10.0.3.58
    instance-id: esnow-local-machine-1
    series: trusty
    hardware: arch=amd64
services:
  postgresql:
    charm: cs:trusty/postgresql-3
    exposed: false
    relations:
      replication:
      - postgresql
    units:
      postgresql/0:
        agent-state: error
        agent-state-info: 'hook failed: "install"'
        agent-version: 1.21-alpha1.1
        machine: "1"
        open-ports:
        - 5432/tcp
        public-address: 10.0.3.58

[Stuart Bishop (stub)]

I will need to see the unit-postgresql-0 log file, in particular the section where the install hook failed.

[Eric Snow (ericsnowcurrently)]

Here some information from the host running postgres:

$ juju run --machine 1 "ps aux | grep post"
root 864 0.0 0.0 294444 10628 ? Ssl 10:19 0:00 /var/lib/juju/tools/unit-postgresql-0/jujud unit --data-dir /var/lib/juju --unit-name postgresql/0 --debug
postgres 3336 0.0 0.6 4135576 105752 ? S 10:19 0:00 /usr/lib/postgresql/9.3/bin/postgres -D /var/lib/postgresql/9.3/main -c config_file=/etc/postgresql/9.3/main/postgresql.conf
postgres 3338 0.0 0.0 4137500 1664 ? Ss 10:19 0:00 postgres: checkpointer process
postgres 3339 0.0 0.1 4137500 26720 ? Ss 10:19 0:00 postgres: writer process
postgres 3340 0.0 0.0 4137500 1664 ? Ss 10:19 0:00 postgres: wal writer process
postgres 3341 0.0 0.0 4138212 2952 ? Ss 10:19 0:00 postgres: autovacuum launcher process
postgres 3342 0.0 0.0 100548 1764 ? Ss 10:19 0:00 postgres: stats collector process
$ juju run --machine 1 "cat /var/log/postgresql/postgresql-9.3-main.log"
2014-08-21 16:19:57 UTC [3337]: [1-1] db=,user= LOG: database system was shut down at 2014-08-21 16:19:55 UTC
2014-08-21 16:19:57 UTC [3336]: [1-1] db=,user= LOG: database system is ready to accept connections
2014-08-21 16:19:57 UTC [3341]: [1-1] db=,user= LOG: autovacuum launcher started
2014-08-21 16:19:58 UTC [3343]: [1-1] db=[unknown],user=[unknown] LOG: incomplete startup packet

[Eric Snow (ericsnowcurrently)]

Manually stopping postgres does not have an effect on the unit:

$ juju run --machine 1 "sudo service postgresql stop"
 * Stopping PostgreSQL 9.3 database server
   ...done.
$ juju run --machine 1 "ps aux | grep post"
root 864 0.0 0.0 294444 10624 ? Ssl 10:19 0:00 /var/lib/juju/tools/unit-postgresql-0/jujud unit --data-dir /var/lib/juju --unit-name postgresql/0 --debug
$ juju run --machine 1 "cat /var/log/postgresql/postgresql-9.3-main.log"
2014-08-21 16:19:57 UTC [3337]: [1-1] db=,user= LOG: database system was shut down at 2014-08-21 16:19:55 UTC
2014-08-21 16:19:57 UTC [3336]: [1-1] db=,user= LOG: database system is ready to accept connections
2014-08-21 16:19:57 UTC [3341]: [1-1] db=,user= LOG: autovacuum launcher started
2014-08-21 16:19:58 UTC [3343]: [1-1] db=[unknown],user=[unknown] LOG: incomplete startup packet
2014-08-21 16:34:00 UTC [3336]: [2-1] db=,user= LOG: received fast shutdown request
2014-08-21 16:34:00 UTC [3336]: [3-1] db=,user= LOG: aborting any active transactions
2014-08-21 16:34:00 UTC [3341]: [2-1] db=,user= LOG: autovacuum launcher shutting down
2014-08-21 16:34:00 UTC [3338]: [1-1] db=,user= LOG: shutting down
2014-08-21 16:34:00 UTC [3338]: [2-1] db=,user= LOG: database system is shut down
$ juju status
environment: local
machines:
  "0":
    agent-state: started
    agent-version: 1.21-alpha1.1
    dns-name: localhost
    instance-id: localhost
    series: trusty
    state-server-member-status: has-vote
  "1":
    agent-state: started
    agent-version: 1.21-alpha1.1
    dns-name: 10.0.3.45
    instance-id: esnow-local-machine-1
    series: trusty
    hardware: arch=amd64
  "2":
    agent-state: started
    agent-version: 1.21-alpha1.1
    dns-name: 10.0.3.245
    instance-id: esnow-local-machine-2
    series: precise
    hardware: arch=amd64
services:
  postgresql:
    charm: cs:trusty/postgresql-3
    exposed: false
    life: dying
    units:
      postgresql/0:
        agent-state: error
        agent-state-info: 'hook failed: "install"'
        agent-version: 1.21-alpha1.1
        life: dying
        machine: "1"
        open-ports:
        - 5432/tcp
        public-address: 10.0.3.45
  reviewboard:
    charm: cs:precise/reviewboard-1
    exposed: true
    units:
      reviewboard/0:
        agent-state: started
        agent-version: 1.21-alpha1.1
        machine: "2"
        open-ports:
        - 80/tcp
        public-address: 10.0.3.245

[Stuart Bishop (stub)]

The install hook failure in all likely hood nothing to do with PostgreSQL itself, but something else like a stuck apt cache lock. Nothing except the ~/.juju/local/log/unit-postgresql-0.log will help diagnose the hook failure.

[Eric Snow (ericsnowcurrently)]

launchpad isn't letting me attach the file so I'm including the last chunk of lines here:

2014-08-22 19:50:21 DEBUG juju-log Running 'getconf PAGE_SIZE'
2014-08-22 19:50:21 INFO juju-log Writing file /etc/sysctl.d/50-postgresql.conf root:root 600
2014-08-22 19:50:21 DEBUG juju-log Running 'sysctl -p /etc/sysctl.d/50-postgresql.conf'
2014-08-22 19:50:21 INFO install sysctl: permission denied on key 'kernel.sem'
2014-08-22 19:50:21 INFO juju-log Writing file /etc/postgresql/9.3/main/postgresql.conf postgres:postgres 600
2014-08-22 19:50:21 DEBUG juju-log Running ['pgtune', '-i', u'/etc/postgresql/9.3/main/postgresql.conf', '-o', '/tmp/tmpYKhaHe', '-T', u'mixed', '-c', '100']
2014-08-22 19:50:21 INFO juju-log Writing file /etc/postgresql/9.3/main/postgresql.conf postgres:postgres 600
2014-08-22 19:50:21 INFO juju-log Writing file /etc/postgresql/9.3/main/pg_ident.conf postgres:postgres 600
2014-08-22 19:50:21 INFO juju-log []
2014-08-22 19:50:21 INFO juju-log Writing file /etc/postgresql/9.3/main/pg_hba.conf postgres:postgres 600
2014-08-22 19:50:21 DEBUG juju-log PostgreSQL is not running
2014-08-22 19:50:21 DEBUG juju-log PostgreSQL is not running
2014-08-22 19:50:21 DEBUG juju-log Running ['pg_ctlcluster', '9.3', u'main', 'start']
2014-08-22 19:50:24 INFO juju-log PostgreSQL started
2014-08-22 19:50:24 INFO install error: cannot open ports 5432-5432/tcp for unit "postgresql/0": cannot open ports 5432-5432/tcp on machine 1 due to conflict
2014-08-22 19:50:24 INFO install 4096
2014-08-22 19:50:24 INFO install
2014-08-22 19:50:24 INFO install kernel.shmall = 4083713
2014-08-22 19:50:24 INFO install
2014-08-22 19:50:24 INFO install kernel.shmmax = 16726885376
2014-08-22 19:50:24 INFO install
2014-08-22 19:50:24 INFO install Traceback (most recent call last):
2014-08-22 19:50:24 INFO install File "/var/lib/juju/agents/unit-postgresql-0/charm/hooks/install", line 2349, in <module>
2014-08-22 19:50:24 INFO install hooks.execute(sys.argv)
2014-08-22 19:50:24 INFO install File "/var/lib/juju/agents/unit-postgresql-0/charm/hooks/charmhelpers/core/hookenv.py", line 478, in execute
2014-08-22 19:50:24 INFO install self._hooks[hook_name]()
2014-08-22 19:50:24 INFO install File "/var/lib/juju/agents/unit-postgresql-0/charm/hooks/install", line 1025, in install
2014-08-22 19:50:24 INFO install config_changed(force_restart=True)
2014-08-22 19:50:24 INFO install File "/var/lib/juju/agents/unit-postgresql-0/charm/hooks/install", line 941, in config_changed
2014-08-22 19:50:24 INFO install update_service_port()
2014-08-22 19:50:24 INFO install File "/var/lib/juju/agents/unit-postgresql-0/charm/hooks/install", line 659, in update_service_port
2014-08-22 19:50:24 INFO install hookenv.open_port(new_port)
2014-08-22 19:50:24 INFO install File "/var/lib/juju/agents/unit-postgresql-0/charm/hooks/charmhelpers/core/hookenv.py", line 415, in open_port
2014-08-22 19:50:24 INFO install subprocess.check_call(_args)
2014-08-22 19:50:24 INFO install File "/usr/lib/python2.7/subprocess.py", line 540, in check_call
2014-08-22 19:50:24 INFO install raise CalledProcessError(retcode, cmd)
2014-08-22 19:50:24 INFO install subprocess.Calle...

[Stuart Bishop (stub)]

2014-08-22 19:50:24 INFO install error: cannot open ports 5432-5432/tcp for unit "postgresql/0": cannot open ports 5432-5432/tcp on machine 1 due to conflict

The charm asked juju to open port 5432, and juju said no and claims there is a conflict. The charm had no choice except to fail.

I think this is either a Juju bug, or you were trying to run two PostgreSQL services (or perhaps PostgreSQL + pgbouncer) in the same virtual machine.

[Eric Snow (ericsnowcurrently)]

It's hard for me to say what it might be. However, juju status does not show more than one postgres service, so it's either a juju core bug or something else, right?

In case it helps, I've verified that postgres is not running before deploying the charm and is running afterward. And likewise from netstat:

tcp 0 0 *:postgresql *:* LISTEN

The offending message seems to happen at the hookenv.open_port() call in the install hook. [1]

[1] https://bazaar.launchpad.net/~charmers/charms/trusty/postgresql/trunk/view/head:/hooks/hooks.py#L1020

[Eric Snow (ericsnowcurrently)]

Here's the full log.

[Eric Snow (ericsnowcurrently)]

Actually, from what happens first in the log file, it look like it happens later in config_changed() [1], when it is called at the end of install().

[1] https://bazaar.launchpad.net/~charmers/charms/trusty/postgresql/trunk/view/head:/hooks/hooks.py#L941

[Eric Snow (ericsnowcurrently)]

So from the logs It looks like install() calls open_port() [1] and then config_changed() later calls open_port() via update_service_port() [2]. For whatever reason the call to update_service_port() does not catch that the port has not changed.

[1] https://bazaar.launchpad.net/~charmers/charms/trusty/postgresql/trunk/view/head:/hooks/hooks.py#L1020
[2] https://bazaar.launchpad.net/~charmers/charms/trusty/postgresql/trunk/view/head:/hooks/hooks.py#L941

[Stuart Bishop (stub)]

I notice Juju 1.21, and recall that work is being done with open-port to support ranges.

I'm flagging this against juju-core as this may be a regression.

[Eric Snow (ericsnowcurrently)]

Good call. I just tried the same dance under 1.20.5 (trusty, local provider) and the postgresql charm deployed without incident.

[Domas Monkus (tasdomas)]

I've submitted a pull request that fixes this problem: https://github.com/juju/juju/pull/667