Service logs only when exiting

Hi everybody,

On an AIX 5.2 system, I have installed daemontools. I didn't notice any
problems during the installation process. I also installed qmail according
to LWQ, which went fine. qmail logging works OK.

Now I'm installing another service: umc. This is a program that is
supplied by MGE along with their UPS systems. It is meant to communicate
with the SNMP agent supplied with our UPS.

When I run this program from a shell prompt, I see the messages as they
are generated:

UMC : Starting UM-Client for AIX
UMC : Internal revision level 0.4
UMC : Starting in verbose mode
UMC : Reading general parameters file
UMC : Reading message file
UMC : Initializing communication level
UMC : Initializing agents table
UMC : Checking plug numbers
UMC : Checking trap port
UMC : Inscription of UM-Client in the agents tables
      Devices  table of agent 172.17.1.99
      Managers table of agent 172.17.1.99
UMC : Checking status of agents
UMC : Initialization successfully completed
UMC : Waiting for a trap

When I type Ctrl-C, the program cleans up and exits:

UMC : Deletion of UM-Client in the agents tables
      Devices  table of agent 172.17.1.99
      Managers table of agent 172.17.1.99
UMC : UM-Client has ended


I have installed umc as a service, which also seems to work just fine.

However, when I start the service by doing "svc -u /service/umclient",
nothing gets written to the logfile. When I wait several minutes, and
do "svc -d /service/umclient", the process is shut down normally. It is
at this point that all information appears in the log, all in one go:

(output of tai64nlocal <current)

2003-08-27 20:11:26.751713500 UMC : Starting UM-Client for AIX
2003-08-27 20:11:26.751727500 UMC : Internal revision level 0.4
2003-08-27 20:11:26.751732500 UMC : Starting in verbose mode
2003-08-27 20:11:26.751737500 UMC : Reading general parameters file
2003-08-27 20:11:26.751743500 UMC : Reading message file
2003-08-27 20:11:26.751748500 UMC : Initializing communication level
2003-08-27 20:11:26.751753500 UMC : Initializing agents table
2003-08-27 20:11:26.751758500 UMC : Checking plug numbers
2003-08-27 20:11:26.751763500 UMC : Checking trap port
2003-08-27 20:11:26.751819500 UMC : Inscription of UM-Client in the agents tables
2003-08-27 20:11:26.751825500       Devices  table of agent 172.17.1.99
2003-08-27 20:11:26.751831500       Managers table of agent 172.17.1.99
2003-08-27 20:11:26.751836500 UMC : Checking status of agents
2003-08-27 20:11:26.751841500 UMC : Initialization successfully completed
2003-08-27 20:11:26.751847500 UMC : Waiting for a trap
2003-08-27 20:11:26.751851500 UMC : Deletion of UM-Client in the agents tables
2003-08-27 20:11:26.751873500       Devices  table of agent 172.17.1.99
2003-08-27 20:11:26.751880500       Managers table of agent 172.17.1.99
2003-08-27 20:11:26.751885500 UMC : UM-Client has ended


Between the "Waiting for a trap"-line and the "Deletion of UM-Client in the
agents tables" lines are actually several minutes.

I do not understand that when I run this program from a shell prompt, the
lines are displayed as they are generated, while multilog seems to get them
in batches. The output generated by qmail-send does appear as it is
generated.



The way this service is set up:

# ls -l /service
total 0
lrwxrwxrwx   1 root     system           32 Aug 27 20:02 clear-errors -> /usr/local/services/clear-errors
lrwxrwxrwx   1 root     system           31 Aug 25 23:34 qmail-send -> /var/qmail/supervise/qmail-send
lrwxrwxrwx   1 root     system           32 Aug 25 23:34 qmail-smtpd -> /var/qmail/supervise/qmail-smtpd
lrwxrwxrwx   1 root     system           30 Aug 27 19:43 umclient -> /usr/upsman/umclient/supervise
# cat /usr/upsman/umclient/supervise/run
#!/bin/sh

sleep 5
exec /usr/upsman/umclient/umc -v
# cat /usr/upsman/umclient/supervise/log/run
#!/bin/sh
exec /usr/local/bin/setuidgid log /usr/local/bin/multilog t /var/log/umclient
# ls -lR /usr/upsman/umclient/supervise
total 8
drwxr-xr-x   4 root     system          256 Aug 27 19:43 log
-rwxr-xr-x   1 root     system           52 Aug 27 20:05 run
drwx------   2 root     system          256 Aug 27 20:13 supervise
/usr/upsman/umclient/supervise/log:
total 8
drwxr-xr-x   2 log      log             256 Aug 27 19:48 main
-rwxr-xr-x   1 root     system           88 Aug 27 18:58 run
drwx------   2 root     system          256 Aug 27 19:51 supervise

/usr/upsman/umclient/supervise/log/main:
total 16
-rw-r--r--   1 log      log            7825 Aug 27 20:11 current
-rw-------   1 log      log               0 Aug 27 19:48 lock
-rw-r--r--   1 log      log               0 Aug 27 19:48 state

/usr/upsman/umclient/supervise/log/supervise:
total 8
prw-------   1 root     system            0 Aug 27 19:51 control
-rw-------   1 root     system            0 Aug 27 19:43 lock
prw-------   1 root     system            0 Aug 27 19:43 ok
-rw-r--r--   1 root     system           18 Aug 27 19:51 status

/usr/upsman/umclient/supervise/supervise:
total 8
prw-------   1 root     system            0 Aug 27 20:13 control
-rw-------   1 root     system            0 Aug 27 19:43 lock
prw-------   1 root     system            0 Aug 27 19:43 ok
-rw-r--r--   1 root     system           18 Aug 27 20:13 status

-- 
Jurjen Oskam

PGP Key available at http://www.stupendous.org/