Bug 6392

I've tested this update on my system. All seems well now.

Source RPM: postgrey-1.34-1.2.mga2.src.rpm in core/updates_testing

Assignee: mageia => qa-bugs

Testing x86_64

Before
------
#urpmi postgrey

# systemctl status postgrey.service
postgrey.service - LSB: Starts the postfix Greylisting Policy Server
          Loaded: loaded (/etc/rc.d/init.d/postgrey)
          Active: inactive (dead)
          CGroup: name=systemd:/system/postgrey.service
                  â 16677 /usr/sbin/postgrey -d --unix=/var/spool/postfix/extern/postgrey/socket --auto-whitelist-clients...

# systemctl start postgrey.service 


Just sits there. so interrupted it with ctrl-c

checking syslog shows..

Jun 14 13:45:40 mega postgrey[19132]: Process Backgrounded
Jun 14 13:45:40 mega postgrey[19132]: 2012/06/14-13:45:40 postgrey (type Net::Server::Multiplex) starting! pid(19132)
Jun 14 13:45:40 mega postgrey[19132]: Using default listen value of 128
Jun 14 13:45:40 mega postgrey[19132]: Binding to UNIX socket file /var/spool/postfix/extern/postgrey/socket using SOCK_STREAM
Jun 14 13:45:40 mega postgrey[19132]: Setting gid to "413 413"
Jun 14 13:45:40 mega postgrey[19132]: Setting uid to "483"
Jun 14 13:45:41 mega postgrey[19122]: Starting postgrey:[  OK  ]
Jun 14 13:45:41 mega systemd[1]: PID file /var/run/greylist.pid not readable (yet?) after start.


After
-----

# ll /var/lib/postgrey/*.lock
-rw------- 1 postgrey postgrey 0 Jun 14 13:45 /var/lib/postgrey/postgrey.lock

There are also problems to the update if the service is started. It can't complete the update process and MageiaUpdate has to be terminated. It leaves both versions installed.

warning: %post(postgrey-1.34-1.2.mga2.noarch) scriptlet failed, signal 2

# urpme postgrey
To satisfy dependencies, the following 2 packages will be removed (181KB):
  postgrey-1.34-1.2.mga2.noarch
  postgrey-1.34-1.mga2.noarch
Remove 2 packages? (y/N) y

It seems to leave a lock file behind when removed, presumably because it isn't finding the pid file and scripts are failing.

# ll /var/lib/postgrey/*.lock
-rw------- 1 postgrey postgrey 0 Jun 14 13:45 /var/lib/postgrey/postgrey.lock

Starting clean..

# rm -rf /var/lib/postgrey
# urpmi postgrey
installing postgrey-1.34-1.2.mga2.noarch.rpm from /var/cache/urpmi/rpms

# systemctl start postgrey.service
# tail /var/log/syslog

Jun 14 13:57:59 mega postgrey[19679]: Starting postgrey:Pid_file "/var/run/postgrey/postgrey.pid" already exists.  Overwriting!
Jun 14 13:57:59 mega postgrey[19689]: Process Backgrounded
Jun 14 13:57:59 mega postgrey[19689]: 2012/06/14-13:57:59 postgrey (type Net::Server::Multiplex) starting! pid(19689)
Jun 14 13:57:59 mega postgrey[19689]: Using default listen value of 128
Jun 14 13:57:59 mega postgrey[19689]: Binding to UNIX socket file /var/spool/postfix/extern/postgrey/socket using SOCK_STREAM
Jun 14 13:57:59 mega postgrey[19689]: Setting gid to "413 413"
Jun 14 13:57:59 mega postgrey[19689]: Setting uid to "483"
Jun 14 13:57:59 mega postgrey[19679]: [  OK  ]


So the updated version seems OK but the update is impossible with the service started.

Assigning back to Colin for now. Please reassign to QA when you've had a chance to look at this.

Thanks!

CC: (none) => qa-bugs
Assignee: qa-bugs => mageia

I've noticed this seems to be a duplicate of bug #5977 I've reported for Cauldron earlier. You might want to look at that bug too, I've attached a fix I'm using now.

CC: (none) => balaton

Hi Zoltan,

This is effectively the same fix I've got here, but I don't do it in the sysconfig file which is fragile and do it instead in the main service file where it cannot be overridden by administrators.

But it's the same basic principle.

The only problem we have here is on upgrade which I need to look at and add hacks to. I'm tempted to not bother as it's going to be ugly to work around :s

*** Bug 5977 has been marked as a duplicate of this bug. ***

I agree, I've only added the fix to the sysconfig file because I used that as a workaround and for that it was cleaner that way. Since my bug seems to be abandoned now I've marked it as a duplicate of this one.

As for the upgrade problem, why isn't it enough to unconditionally clean the stale lock file in the %pre script by adding a line
rm -f /var/lib/postgrey/postgrey.lock
to that part in the spec file? Does that introduce any other problem?

Sorry for "abandoning" your bug. I wasn't aware of it when I noticed the problem, so just submitted a new bug. Lazy me :)

The lock cannot simply be removed as the there is technically a postgrey daemon running already, it's just that systemd doesn't really consider that the service has succeeded due to the pid file problem.

Thus, while it is in this failed state, try-restart will not work.

Note that the various commands that were manually terminated in the testing above would have timed out after 5 minutes, so no manual intervention is required here, but people do need to be patient.

I've got a (somewhat horrible) work around that I am testing now.

OK, a new package has been pushed to updates_testing.

This package contains a work around for the problems reported here.



If the service has failed or is currently activating (e.g. within the 5 minute timeout period), but a binary is running (as would be the typical setup of this service running on mga2 approx 5mins after boot), then the system will kill that binary (which releases it's lock), and set a flag such that the service will be started properly after the new package is installed (the try-restart which happens automatically will not start the service as it's in it's failed state).

This should work around the problems highlighted by Claire (it does for me).


Below is the output from two different testing scenarios (started, but waited 5mins for the timeout; and started but still activating (i.e. < 5mins)). All of the command completed in a timely fashion (e.g. no waiting).



[root@marley ~]# systemctl status postgrey.service 
postgrey.service - LSB: Starts the postfix Greylisting Policy Server
    Loaded: loaded (/etc/rc.d/init.d/postgrey)
    Active: failed (Result: timeout) since Tue, 26 Jun 2012 11:19:51 +0100; 5min ago
    CGroup: name=systemd:/system/postgrey.service
      â 4102 /usr/sbin/postgrey -d --unix=/var/spool/postfix/extern/postgrey/socket --auto-whitelist-clients

Jun 26 11:14:51 marley.rasta.guthr.ie postgrey[4102]: Process Backgrounded
Jun 26 11:14:51 marley.rasta.guthr.ie postgrey[4102]: 2012/06/26-11:14:51 postgrey (type Net::Server::Multiplex) starting! pid(4102)
Jun 26 11:14:51 marley.rasta.guthr.ie postgrey[4102]: Using default listen value of 128
Jun 26 11:14:51 marley.rasta.guthr.ie postgrey[4102]: Binding to UNIX socket file /var/spool/postfix/extern/postgrey/socket using SOCK_STREAM
Jun 26 11:14:51 marley.rasta.guthr.ie postgrey[4102]: Setting gid to "91 91"
Jun 26 11:14:51 marley.rasta.guthr.ie postgrey[4102]: Setting uid to "91"

[root@marley ~]# rpm -Uvh /home/colin/postgrey-1.34-1.2.1.csg3.noarch.rpm 
Preparing...                ########################################### [100%]
   1:postgrey               ########################################### [100%]

[root@marley ~]# systemctl status postgrey.service 
postgrey.service - LSB: Starts the postfix Greylisting Policy Server
    Loaded: loaded (/etc/rc.d/init.d/postgrey)
    Active: active (running) since Tue, 26 Jun 2012 11:25:41 +0100; 3s ago
   Process: 4354 ExecStart=/etc/rc.d/init.d/postgrey start (code=exited, status=0/SUCCESS)
  Main PID: 4371 (/usr/sbin/postg)
    CGroup: name=systemd:/system/postgrey.service
      â 4371 /usr/sbin/postgrey -d --pidfile=/var/run/postgrey/postgrey.pid --unix=/var/spool/postfix/extern/postgrey/socke...

Jun 26 11:25:41 marley.rasta.guthr.ie postgrey[4371]: Process Backgrounded
Jun 26 11:25:41 marley.rasta.guthr.ie postgrey[4371]: 2012/06/26-11:25:41 postgrey (type Net::Server::Multiplex) starting! pid(4371)
Jun 26 11:25:41 marley.rasta.guthr.ie postgrey[4371]: Using default listen value of 128
Jun 26 11:25:41 marley.rasta.guthr.ie postgrey[4371]: Binding to UNIX socket file /var/spool/postfix/extern/postgrey/socket using SOCK_STREAM
Jun 26 11:25:41 marley.rasta.guthr.ie postgrey[4371]: Setting gid to "91 91"
Jun 26 11:25:41 marley.rasta.guthr.ie postgrey[4371]: Setting uid to "91"








[root@marley ~]# systemctl start --no-block postgrey.service

[root@marley ~]# systemctl status postgrey.service 
postgrey.service - LSB: Starts the postfix Greylisting Policy Server
    Loaded: loaded (/etc/rc.d/init.d/postgrey)
    Active: activating (start) since Tue, 26 Jun 2012 11:32:54 +0100; 5s ago
   Process: 4733 ExecStart=/etc/rc.d/init.d/postgrey start (code=exited, status=0/SUCCESS)
    CGroup: name=systemd:/system/postgrey.service
      â 4743 /usr/sbin/postgrey -d --unix=/var/spool/postfix/extern/postgrey/socket --auto-whitelist-clients

Jun 26 11:32:54 marley.rasta.guthr.ie postgrey[4743]: Process Backgrounded
Jun 26 11:32:54 marley.rasta.guthr.ie postgrey[4743]: 2012/06/26-11:32:54 postgrey (type Net::Server::Multiplex) starting! pid(4743)
Jun 26 11:32:54 marley.rasta.guthr.ie postgrey[4743]: Using default listen value of 128
Jun 26 11:32:54 marley.rasta.guthr.ie postgrey[4743]: Binding to UNIX socket file /var/spool/postfix/extern/postgrey/socket using SOCK_STREAM
Jun 26 11:32:54 marley.rasta.guthr.ie postgrey[4743]: Setting gid to "91 91"
Jun 26 11:32:54 marley.rasta.guthr.ie postgrey[4743]: Setting uid to "91"

[root@marley ~]# rpm -Uvh /home/colin/postgrey-1.34-1.2.1.csg3.noarch.rpm 
Preparing...                ########################################### [100%]
   1:postgrey               ########################################### [100%]

[root@marley ~]# systemctl status postgrey.service 
postgrey.service - LSB: Starts the postfix Greylisting Policy Server
    Loaded: loaded (/etc/rc.d/init.d/postgrey)
    Active: active (running) since Tue, 26 Jun 2012 11:33:09 +0100; 1s ago
   Process: 4794 ExecStart=/etc/rc.d/init.d/postgrey start (code=exited, status=0/SUCCESS)
  Main PID: 4811 (/usr/sbin/postg)
    CGroup: name=systemd:/system/postgrey.service
      â 4811 /usr/sbin/postgrey -d --pidfile=/var/run/postgrey/postgrey.pid --unix=/var/spool/postfix/extern/postgrey/socke...

Jun 26 11:33:09 marley.rasta.guthr.ie postgrey[4811]: Process Backgrounded
Jun 26 11:33:09 marley.rasta.guthr.ie postgrey[4811]: 2012/06/26-11:33:09 postgrey (type Net::Server::Multiplex) starting! pid(4811)
Jun 26 11:33:09 marley.rasta.guthr.ie postgrey[4811]: Using default listen value of 128
Jun 26 11:33:09 marley.rasta.guthr.ie postgrey[4811]: Binding to UNIX socket file /var/spool/postfix/extern/postgrey/socket using SOCK_STREAM
Jun 26 11:33:09 marley.rasta.guthr.ie postgrey[4811]: Setting gid to "91 91"
Jun 26 11:33:09 marley.rasta.guthr.ie postgrey[4811]: Setting uid to "91"
Jun 26 11:33:09 marley.rasta.guthr.ie postgrey[4794]: Starting postgrey:[  OK  ]

I think this update can be pushed now.

Thankyou Colin.

Retesting i586.

Before
------

# systemctl status postgrey.service 
postgrey.service - LSB: Starts the postfix Greylisting Policy Server
          Loaded: loaded (/etc/rc.d/init.d/postgrey)
          Active: inactive (dead)
          CGroup: name=systemd:/system/postgrey.service

# systemctl start postgrey.service 

interrupted with ctrl-c

# tail /var/log/syslog
Jul  7 13:09:14 laptop systemd[1]: Reloading.
Jul  7 13:09:16 laptop systemd[1]: Reloading.
Jul  7 13:10:41 laptop postgrey[9112]: Process Backgrounded
Jul  7 13:10:41 laptop postgrey[9112]: 2012/07/07-13:10:41 postgrey (type Net::Server::Multiplex) starting! pid(9112)
Jul  7 13:10:41 laptop postgrey[9112]: Using default listen value of 128
Jul  7 13:10:41 laptop postgrey[9112]: Binding to UNIX socket file /var/spool/postfix/extern/postgrey/socket using SOCK_STREAM
Jul  7 13:10:41 laptop postgrey[9112]: Setting gid to "466 466"
Jul  7 13:10:41 laptop postgrey[9112]: Setting uid to "466"
Jul  7 13:10:41 laptop postgrey[9102]: Starting postgrey:[  OK  ]
Jul  7 13:10:41 laptop systemd[1]: PID file /var/run/greylist.pid not readable (yet?) after start.


After
-----

# MageiaUpdate

Updated postgrey. No problems.

# systemctl status postgrey.service 
postgrey.service - LSB: Starts the postfix Greylisting Policy Server
          Loaded: loaded (/etc/rc.d/init.d/postgrey)
          Active: active (running) since Sat, 07 Jul 2012 13:12:30 +0100; 50s ago
         Process: 9249 ExecStart=/etc/rc.d/init.d/postgrey start (code=exited, status=0/SUCCESS)
        Main PID: 9264 (/usr/sbin/postg)
          CGroup: name=systemd:/system/postgrey.service
                  â 9264 /usr/sbin/postgrey -d --pidfile=/var/run/postgrey/po...

Jul 07 13:12:30 laptop postgrey[9264]: Process Backgrounded
Jul 07 13:12:30 laptop postgrey[9264]: 2012/07/07-13:12:30 postgrey (type Net...4)
Jul 07 13:12:30 laptop postgrey[9264]: Using default listen value of 128
Jul 07 13:12:30 laptop postgrey[9264]: Binding to UNIX socket file /var/spool...AM
Jul 07 13:12:30 laptop postgrey[9264]: Setting gid to "466 466"
Jul 07 13:12:30 laptop postgrey[9264]: Setting uid to "466"
Jul 07 13:12:30 laptop postgrey[9249]: Starting postgrey:[  OK  ]


So great stuff, seems fixed :)

I'll test x86_64 aswell, is there a simple way to check it's working Colin?

Tested x86_64 too, the problem with updating is fixed and the service starts successfully.

It would be good to be able to show it works though. I believe that can be done through a telnet session. I can telnet to localhost on port 10026 but not sure how to test postgrey is working.

I can see in /var/log/mail/info.log that postgrey is loaded so I guess that at least shows there are no errors. The service starts/stops/restarts ok. No errors in syslog either.

Short of configuring a full mailserver I think this is sufficient to validate.


=== Advisory Text ===

The postgrey package shipped with Mageia 2 contained incorrect pidfile
configurations. This prevented the service status from being properly reported
in systemd and prevented proper service management.

This update corrects the pidfile location which allows systemd to control
postgrey correctly.

SRPM: postgrey-1.34-1.3.mga2.src.rpm

Could sysadmin please push from core/updates_testing to core/updates

Thanks!

Keywords: (none) => validated_update
CC: (none) => sysadmin-bugs
Hardware: i586 => All
Whiteboard: (none) => mga2-32-OK mga2-64-OK

Update pushed:
https://wiki.mageia.org/en/Support/Advisories/MGAA-2012-0106

Status: NEW => RESOLVED
CC: (none) => tmb
Resolution: (none) => FIXED