Procd_set_param stdout/stderr 1 not functioning

For Developers
#1

(SOLUTION NOTE: The problem is that the service, written in python, buffers it's stdout/stderr. Unbuffered output can be designated by adding -u to the command, or by setting the env var PYTHONBUFFERED=0.
For serious logging it is better to send directly to /dev/log, e.g. use the Python module logging.handlers.SysLogHandler and avoid the extra layer of going through procd indirection. For example it was found that procd did not report a Connection Failed 111 error for /dev/log when it was in an error state.
Thanks to @yousong@ for their great help and "no buffering" solution to this problem.)

I have written a service file with procd commands.
The service runs and functions correctly but the log output is not output the buffer shown by logread.

The start_service() function is as follows:

DGH_CMD="/usr/bin/python3 /work/dgh/dns-mitm.py"
DGH_PARAM=" -b 192.168.11.24 -v 2" 

...

start_service() {

  procd_open_instance dgh
  procd_set_param command $DGH_CMD
  procd_append_param command $DGH_PARAM

  # respawn automatically if something died,
  # be careful if you have an alternative process supervisor
  # if process dies sooner than respawn_threshold,
  # it is considered crashed and after 5 retries the service is stopped
  procd_set_param respawn ${respawn_threshold:-3600} ${respawn_timeout:-5} ${respawn_retry:-5}

  procd_set_param user root # run service as user nobody
  procd_set_param limits core="unlimited"  # If you need to set ulimit for your process
  # forward stdout and stderr of the command to logd
  procd_set_param stdout 1 
  procd_set_param stderr 1
  procd_set_param pidfile /var/run/dgh.service.pid # write a pid file on instance start and remote it on stop
  procd_close_instance

	
    echo "dgh: start_service() invoking $DGH_CMD RESULT=$?" 
		
}

I also tested with procd_close_instance removed - no difference and it still ran.

#  procd_close_instance

I noticed that the only other service files files in my setup (which amd64 18.06.2 release) which contain procd_set_param stdout 1 or procd_set_param stderr 1 are

  • uhttpd
  • urandom_seed

For a test I restarted these services to see if anything would show up with logread, but nothing did. Of course that is proof of nothing, except that I couldn't eliminate that possibility that procd_set_param stdout/stderr 1 isn't functioning. Other logging such as from dropbear and nftables are working correctly, but dropbear is not using the procd_set_param stdout/stderr 1 in its service file.

Is there another way to set logging?

#2 
Usage: logger [OPTIONS] [MESSAGE]

Write MESSAGE (or stdin) to syslog

	-s	Log to stderr as well as the system log
	-t TAG	Log using the specified tag (defaults to user name)
	-p PRIO	Priority (numeric or facility.level pair)
1 Like
#3

I tried this:

I one terminal:

# logread -f

In the other:

# logger  "test"

# logger  -s "test"
root: test

It seems like logd is running and other do appear with logread (dropbear, dhcp, etc.)

root@OpenWrt:~# ps | grep logd
16140 root      7048 S    /sbin/logd -S 64

I am looking at source code for logd.c

 238 int main(int argc, char **argv)
 239 {
 240         int ch, log_size = 16;
 241 
 242         signal(SIGPIPE, SIG_IGN);
 243         while ((ch = getopt(argc, argv, "S:")) != -1) {
 244                 switch (ch) {
 245                 case 'S':
 246                         log_size = atoi(optarg);
 247                         if (log_size < 1)
 248                                 log_size = 16;
 249                         break;
 250                 }
 251         }
 252         log_size *= 1024;
 253 
 254         uloop_init();
 255         log_init(log_size);
 256         conn.cb = ubus_connect_handler;
 257         ubus_auto_connect(&conn);
 258         uloop_run();
 259         log_shutdown();
 260         uloop_done();
 261         ubus_auto_shutdown(&conn);
 262 
 263         return 0;
 264 }

and it looks like it is reading from ubus, but I have no know idea how logging via ubus works.

#4

I'm using "procd_set_param std..." just like you with some scripts, and the messages do end on the logs. Perhaps there is something special with your program?

1 Like
#5

Pleas share output of the following commands. They should help debug the issue further.

ubus call service list '{"name": "<service-name>", "verbose": true}'
ls -al /proc/<instance-pid>/fd/
1 Like
#6

@yousong Thanks - does this look normal - or not?

root@OpenWrt:~# ubus call service list '{"name": "dgh", "verbose": true}'
{
	"dgh": {
		"instances": {
			"data": {
				"running": false,
				"term_timeout": 5
			},
			"dgh": {
				"running": true,
				"pid": 16096,
				"command": [
					"\/usr\/bin\/python3",
					"\/work\/dgh\/dns-mitm.py",
					"-b",
					"192.168.11.24",
					"-v",
					"1"
				],
				"term_timeout": 5,
				"limits": {
					"core": "unlimited"
				},
				"respawn": {
					"threshold": 3600,
					"timeout": 5,
					"retry": 5
				},
				"pidfile": "\/var\/run\/dgh.service.pid"
			}
		}
	}
}
root@OpenWrt:~# ls -al /proc/16096/fd
dr-x------    2 root     root             0 May 22 02:36 .
dr-xr-xr-x    8 root     root             0 May 22 02:36 ..
lr-x------    1 root     root            64 May 22 04:12 0 -> /dev/null
l-wx------    1 root     root            64 May 22 04:12 1 -> pipe:[32723]
l-wx------    1 root     root            64 May 22 04:12 2 -> pipe:[32724]
lrwx------    1 root     root            64 May 22 02:36 3 -> socket:[36590]
lrwx------    1 root     root            64 May 22 04:12 4 -> anon_inode:[eventpoll]
#7

It's a python script, but when run in a terminal (as opposed to being called as a service) the output appears normal.

It is a single thread program. Output is using the python print(...) function.

#8

Yes, procd has piped up stdout and stderr. It should work.

I have a dummy pservice package for wrapping simple commands such as ssh, wpa_supplicant, shell scripts, etc. as procd service, and it works. Will try it later against 18.06.2

#9

@yousong

For comparison, I also got the data for dropbear, for which logging is working correctly (logread shows the data).

root@OpenWrt:~# ubus call service list '{"name": "dropbear", "verbose": true}'
{
	"dropbear": {
		"instances": {
			"instance1": {
				"running": true,
				"pid": 1819,
				"command": [
					"\/usr\/sbin\/dropbear",
					"-F",
					"-P",
					"\/var\/run\/dropbear.1.pid",
					"-p",
					"22",
					"-K",
					"300",
					"-T",
					"3"
				],
...

root@OpenWrt:~# ls -al /proc/1819/fd
dr-x------    2 root     root             0 May 18 08:53 .
dr-xr-xr-x    8 root     root             0 May 14 04:13 ..
lr-x------    1 root     root            64 May 18 08:53 0 -> /dev/null
l-wx------    1 root     root            64 May 18 08:53 1 -> /dev/null
l-wx------    1 root     root            64 May 18 08:53 2 -> /dev/null
lrwx------    1 root     root            64 May 18 08:53 3 -> socket:[1359]
lrwx------    1 root     root            64 May 18 08:53 4 -> socket:[1360]
lrwx------    1 root     root            64 May 18 08:53 5 -> socket:[1361]

Strangely, in the case of dropbear, fd's 1 and 2 are mapped to /dev/null.

#10

dropbear uses syslog directly. It does not rely on procd to record and syslog for it.

#11

What do you mean by syslog? A daemon? My setuphas no package, program, or process named syslog, or syslog*.

I do have a package, program, and process names logd.

root@OpenWrt:~# ps | grep logd
16140 root      7048 S    /sbin/logd -S 64
#12

I mean syslog() call that writes to e.g. /dev/log directly. logd is the syslog daemon in OpenWrt.

1 Like
#13

Running this program with python3 didn't put any output visible with logread (although dropbear does).

import syslog
syslog.syslog('Processing started')
syslog.syslog(syslog.LOG_ERR, 'Processing error')
#14

Likely something is not doing right with logd, but I cannot reproduce here.

Maybe you can try restarting logd by doing /etc/init.d/log restart and see if things start to work

I wrote a simple test script

. /lib/functions/procd.sh
service_triggers() { true; }
procd_open_service foo foo
procd_open_instance bar
procd_set_param command '/tmp/b.sh'
procd_set_param stdout 1
procd_close_instance
procd_close_service

and b.sh

#!/bin/sh

while true; do
        logger "xxx `date`"
        echo "xxy `date`"
        sleep 3
done

Both xxx and xxy can be read with from logread

2 Likes
#15

Running procd.sh I get an error:

root@OpenWrt:/test# ./procd.sh 
BusyBox v1.28.4 () multi-call binary.

Usage: basename FILE [SUFFIX]

Strip directory path and .SUFFIX from FILE
./procd.sh: line 1: service_data: not found

EDIT: However, the results are reaching logd and showing up with logread.

I tried adding this to my service script:

service_triggers() {      
    echo "dgh: service_triggers"  
    true;                            
}

It gets called but it doesn't solve the problem.

EDIT: I tried replacing the shell file b.sh with a similar python file c.py

import time
while True:
    print( time.time() )
    time.sleep(3)

The contents of procd.sh:

. /lib/functions/procd.sh
service_triggers() { true; }
procd_open_service foo foo
procd_open_instance bar
procd_set_param command '/usr/bin/python3 /test/c.py'
#procd_set_param command '/test/b.sh'
procd_set_param stdout 1
procd_close_instance
procd_close_service
ps | grep -e 'test'

The result:

root@OpenWrt:/test# ./procd.sh
BusyBox v1.28.4 () multi-call binary.

Usage: basename FILE [SUFFIX]

Strip directory path and .SUFFIX from FILE
./procd.sh: line 1: service_data: not found
 9405 root      3092 S    grep -e test
root@OpenWrt:/test#

The expected process /usr/bin/python3 /test/c.py is not even present.

Sanity check:

root@OpenWrt:/test# /usr/bin/python3 /test/c.py
1558565128.754266
1558565131.7571716

It seems like there is some bad blood between procd.sh and python3.

In the case of the my service, at least the python process was started and running - as far as I know only the logging was problematic.

As I wrote in another post, I am going to try to solve my problem by avoiding the procd redirection and logging to /dev/log directly.

#16

@yousong

Following on your discussion of /dev/log, I tested at that level directly. This python3 program:

import socket
s = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
s.connect('/dev/log')
s.send(b"test from test.py\n")

At first it failed with [Errno 111] Connection refused. So I rebooted. Then it succeeded:

Wed May 22 20:09:57 2019 kern.emerg test from test.py

I thought that the problem with the procd service must be solved! But unfortunately it still wasn't working. The service still isn't routing stdout/stderr to logd.

I am going to solve my immediate problem of logging the service by using the socket directly in the program source code - e.g., python has logging module where /dev/log can be specified - instead of print(...).

Unfortunately the original question of why procd_set_param stdout 1 isn't working remains unresolved. It's also unclear how/why /dev/log could refuse connections, even as it continued to log dropbear, dnsmasq, and other programs. And apparently the latter problem is not a cause of the former problem.

#17

Likely caused by timing. It takes a moment for the process to actually appear.

As for the /dev/log socket connection refused issue. Do you happen to have like other syslog daemons installed? When this issue appears again, can you check with lsof to see what's the current users of /dev/log and what logd is referring to. Maybe stat and inode can reveal this difference, but I am nore sure without trying.

#18

@yousong

At the time of posting I had already tried inserting various sleeps into the procd.sh shell script, run multiple times, and executed ps | grep test manually multiple times, because I was certain the test python prog c.py must be running. But in the end, I could find no evidence of it running, unlike the test shell script b.sh.

Probably it is inconvenient for you to test because python3 is seldom installed in OpenWRT due to size and CPU computing power constraints. For that same reason testing procd-python combination is probably not a release standard. Or maybe it is just my setup.

Re: the "/dev/log socket connection refused error", if the cause were an obscure side effect of rerouting a python programs stdout/stderr through ubus to get to /dev/log, then it won't happen again because now the program is logging directly to /dev/log by using the python3 logging.handlers.SysLogHandler feature. But if that error does happen again I will let you know.

Your posts were very helpful in moving me quickly to avoid relying the procd redirection and logging directly to /dev/log instead. Thanks!

#19

Tried it myself with python3 inside QEMU

In the quoted line below, the quotes need to be removed. Otherwise procd will take the whole as argv[0]

As for the stdout not reaching logd immediately, it's because python has stdio buffering magic. This can observed with strace, no write(1, "xxx") can be observed initially.

Try the following commands

python3 -c 'import time; print("hello"); time.sleep(3600)' | cat
python3 -u -c 'import time; print("hello"); time.sleep(3600)' | cat
PYTHONUNBUFFERED=1 python3 -c 'import time; print("hello"); time.sleep(3600)' | cat
1 Like
#20

@yousong

Nice catch!

So un-buffering the stdout/stderr get's python to work and procd and stdout/stderr redirection.

Add the -u option after python3 is equivalent to setting PYTHONBUFFERED=0.

So with the command line

procd_set_param command /usr/bin/python3 -u /test/c.py

the following output appears in real time with logread -f

Fri May 24 23:43:22 2019 daemon.info python3[15641]: 1558741402.8371658
Fri May 24 23:43:25 2019 daemon.info python3[15641]: 1558741405.8403313
...

In conclusion,
a. using python in unbuffered mode works with procd and log redirection, b. using python in buffered mode with procd and log redirection is broken to some degree.

How broken is it? At least two problems:

  1. log output is not viewable immediately because it is buffered. Immediately does not imply "only a short time".
  2. When connecting to /dev/log fails at startup, that connection error is not reported when executing service <service name> start.

An unknown is whether (1.) is related to the cause of un-connectable socket error mentioned in (2.)

I am marking your above post as a solution because it answers the title question.

For reference I include code for Python3 logging module logging to directly to /dev/log, which worked on OpenWRT.

    logger = logging.getLogger("dgh-srv")
    logger.setLevel(logging.DEBUG)
    handler = logging.handlers.SysLogHandler(
        facility=logging.handlers.SysLogHandler.LOG_DAEMON,
        address="/dev/log",
        socktype=socket.SOCK_DGRAM)
    handler.setLevel(logging.DEBUG)
    logger.addHandler(handler)