Bug 6392 - Service status for postgrey incorrectly reported
Summary: Service status for postgrey incorrectly reported
Status: RESOLVED FIXED
Alias: None
Product: Mageia
Classification: Unclassified
Component: RPM Packages (show other bugs)
Version: 2
Hardware: All Linux
Priority: Normal normal
Target Milestone: ---
Assignee: QA Team
QA Contact:
URL:
Whiteboard: mga2-32-OK mga2-64-OK
Keywords: validated_update
: 5977 (view as bug list)
Depends on:
Blocks:
 
Reported: 2012-06-09 21:08 CEST by Colin Guthrie
Modified: 2012-07-10 17:21 CEST (History)
4 users (show)

See Also:
Source RPM: postgrey-1.34-1.mga2.src.rpm
CVE:
Status comment:


Attachments

Description Colin Guthrie 2012-06-09 21:08:35 CEST
=== 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.
Comment 1 Colin Guthrie 2012-06-09 21:09:48 CEST
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

Comment 2 claire robinson 2012-06-14 15:00:49 CEST
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.
Comment 3 claire robinson 2012-06-18 15:38:00 CEST
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

Comment 4 Zoltan Balaton 2012-06-25 17:53:09 CEST
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

Comment 5 Colin Guthrie 2012-06-25 19:03:42 CEST
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
Comment 6 Zoltan Balaton 2012-06-25 22:50:43 CEST
*** Bug 5977 has been marked as a duplicate of this bug. ***
Comment 7 Zoltan Balaton 2012-06-25 22:59:47 CEST
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?
Comment 8 Colin Guthrie 2012-06-26 12:20:36 CEST
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.
Comment 9 Colin Guthrie 2012-06-26 12:41:04 CEST
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  ]
Colin Guthrie 2012-06-26 12:41:15 CEST

Assignee: mageia => qa-bugs

Comment 10 Colin Guthrie 2012-07-07 12:10:28 CEST
I think this update can be pushed now.
Comment 11 claire robinson 2012-07-07 13:53:34 CEST
Thankyou Colin.

Retesting i586.
Comment 12 claire robinson 2012-07-07 14:24:27 CEST
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?
Comment 13 claire robinson 2012-07-07 14:59:44 CEST
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.
Comment 14 claire robinson 2012-07-07 15:26:12 CEST
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

Comment 15 Thomas Backlund 2012-07-10 17:21:57 CEST
Update pushed:
https://wiki.mageia.org/en/Support/Advisories/MGAA-2012-0106

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


Note You need to log in before you can comment on or make changes to this bug.