[OpenWrt-Devel,procd] service: use PTY (instead of a pipe) for reading service output

Using pipe automatically switches service to block buffering which kind
of breaks our logging. We won't get anything from FD until the buffer
gets filled fully or the service exits. This makes log messages appear
with an unwanted delay.
Switching to PTY fixes this issue. Service prints to the "standard"
stdout (no piping) but the messages go (line buffered) to the master FD
anyway.
It was successfully tested with all 4 variants of "stdout" and "stderr"
ubus arguments.

Signed-off-by: Rafał Miłecki <zajec5@gmail.com>
---
 CMakeLists.txt     |  2 +-
 service/instance.c | 35 +++++++++++++++++++++++++----------
 2 files changed, 26 insertions(+), 11 deletions(-)

On 19 June 2015 at 19:34, Rafał Miłecki <zajec5@gmail.com> wrote:
> Using pipe automatically switches service to block buffering which kind
> of breaks our logging. We won't get anything from FD until the buffer
> gets filled fully or the service exits. This makes log messages appear
> with an unwanted delay.
> Switching to PTY fixes this issue. Service prints to the "standard"
> stdout (no piping) but the messages go (line buffered) to the master FD
> anyway.
> It was successfully tested with all 4 variants of "stdout" and "stderr"
> ubus arguments.
>

I do not like this because

 - Conventionally, services will drop their inherited controlling
terminal for preparation of becoming a daemon.  Adding back that
controlling terminal by login_tty() for alleviating possible delay
when logging stdio sounds not right.
 - I am biased... in that the ossherd [1] package depends on the fact
processes started by procd do not have controlling terminals and this
will unattended password login with ssh  :)

Anyway, the implementation is not complete.

 - epipe[] is still there.
 - aslave needs to be closed when login_pty() failed
 - login_pty() and dup2() used together
 - aslave should be closed in parent

Cheers

                yousong


> Signed-off-by: Rafał Miłecki <zajec5@gmail.com>
> ---
>  CMakeLists.txt     |  2 +-
>  service/instance.c | 35 +++++++++++++++++++++++++----------
>  2 files changed, 26 insertions(+), 11 deletions(-)
>
> diff --git a/CMakeLists.txt b/CMakeLists.txt
> index dfa9413..7e1fad3 100644
> --- a/CMakeLists.txt
> +++ b/CMakeLists.txt
> @@ -14,7 +14,7 @@ SET(SOURCES procd.c signal.c watchdog.c state.c       inittab.c rcS.c ubus.c system.c
>         service/service.c service/instance.c service/validate.c service/trigger.c service/watch.c
>         plug/coldplug.c plug/hotplug.c utils/utils.c)
>
> -SET(LIBS ubox ubus json-c blobmsg_json json_script)
> +SET(LIBS util ubox ubus json-c blobmsg_json json_script)
>
>  IF(DEBUG)
>    ADD_DEFINITIONS(-DDEBUG -g3)
> diff --git a/service/instance.c b/service/instance.c
> index 35b2def..110db36 100644
> --- a/service/instance.c
> +++ b/service/instance.c
> @@ -23,6 +23,8 @@
>  #include <pwd.h>
>  #include <libgen.h>
>  #include <unistd.h>
> +#include <pty.h>
> +#include <utmp.h>
>
>  #include <libubox/md5.h>
>
> @@ -273,7 +275,7 @@ instance_run(struct service_instance *in, int _stdout, int _stderr)
>                 dup2(_stdin, STDIN_FILENO);
>                 closefd(_stdin);
>         }
> -       if (_stdout > -1) {
> +       if (_stdout > -1 && _stdout != STDOUT_FILENO) {
>                 dup2(_stdout, STDOUT_FILENO);
>                 closefd(_stdout);
>         }
> @@ -314,8 +316,9 @@ instance_free_stdio(struct service_instance *in)
>  void
>  instance_start(struct service_instance *in)
>  {
> +       int amaster = -1, aslave = -1;
>         int pid;
> -       int opipe[2] = { -1, -1 };
> +       int _stdout = -1;
>         int epipe[2] = { -1, -1 };
>
>         if (!avl_is_empty(&in->errors.avl)) {
> @@ -327,13 +330,19 @@ instance_start(struct service_instance *in)
>                 return;
>
>         instance_free_stdio(in);
> +
> +       /* We don't want block buffered stdout so use PTY instead of a pipe */
>         if (in->_stdout.fd.fd > -2) {
> -               if (pipe(opipe)) {
> -                       ULOG_WARN("pipe() failed: %d (%s)\n", errno, strerror(errno));
> -                       opipe[0] = opipe[1] = -1;
> +               if (openpty(&amaster, &aslave, NULL, NULL, NULL)) {
> +                       ULOG_WARN("openpty() failed: %d (%s)\n", errno, strerror(errno));
> +                       amaster = aslave = -1;
> +               } else {
> +                       /* Child should just use stdout which will go to the master */
> +                       _stdout = STDOUT_FILENO;
>                 }
>         }
>
> +       /* Use pipe as stderr is always unbuffered by default */
>         if (in->_stderr.fd.fd > -2) {
>                 if (pipe(epipe)) {
>                         ULOG_WARN("pipe() failed: %d (%s)\n", errno, strerror(errno));
> @@ -353,9 +362,15 @@ instance_start(struct service_instance *in)
>
>         if (!pid) {
>                 uloop_done();
> -               closefd(opipe[0]);
> +               close(amaster);
>                 closefd(epipe[0]);
> -               instance_run(in, opipe[1], epipe[1]);
> +               if (aslave > -1) {
> +                       if (login_tty(aslave)) {
> +                               ULOG_WARN("login_tty() failed: %d (%s)\n", errno, strerror(errno));
> +                               _stdout = -1;
> +                       }
> +               }
> +               instance_run(in, _stdout, epipe[1]);
>                 return;
>         }
>
> @@ -364,9 +379,9 @@ instance_start(struct service_instance *in)
>         clock_gettime(CLOCK_MONOTONIC, &in->start);
>         uloop_process_add(&in->proc);
>
> -       if (opipe[0] > -1) {
> -               ustream_fd_init(&in->_stdout, opipe[0]);
> -               closefd(opipe[1]);
> +       if (amaster > -1) {
> +               ustream_fd_init(&in->_stdout, amaster);
> +               closefd(aslave);
>         }
>
>         if (epipe[0] > -1) {
> --
> 1.8.4.5
> _______________________________________________
> openwrt-devel mailing list
> openwrt-devel@lists.openwrt.org
> https://lists.openwrt.org/cgi-bin/mailman/listinfo/openwrt-devel

On 19 June 2015 at 14:44, Yousong Zhou <yszhou4tech@gmail.com> wrote:
> On 19 June 2015 at 19:34, Rafał Miłecki <zajec5@gmail.com> wrote:
>> Using pipe automatically switches service to block buffering which kind
>> of breaks our logging. We won't get anything from FD until the buffer
>> gets filled fully or the service exits. This makes log messages appear
>> with an unwanted delay.
>> Switching to PTY fixes this issue. Service prints to the "standard"
>> stdout (no piping) but the messages go (line buffered) to the master FD
>> anyway.
>> It was successfully tested with all 4 variants of "stdout" and "stderr"
>> ubus arguments.
>>
>
> I do not like this because
>
>  - Conventionally, services will drop their inherited controlling
> terminal for preparation of becoming a daemon.  Adding back that
> controlling terminal by login_tty() for alleviating possible delay
> when logging stdio sounds not right.

Do you have any other idea?
The delay isn't "possible", I think it occurs with 90%+ of apps. I'm
not aware of many apps (except for grep maybe) that calls "fflush"
after every printf. It simply makes reading real-time logs with
"logread" not working at all.


>  - I am biased... in that the ossherd [1] package depends on the fact
> processes started by procd do not have controlling terminals and this
> will unattended password login with ssh  :)

I'm afraid I don't understand this part. In any case, you don't have
to use logging in your init.d script. It's an option.


> Anyway, the implementation is not complete.
>
>  - epipe[] is still there.

It is supposed to be. That's the only way to keep logging of stdout
and stderr separated. Read my comment (in the code) about epipe.


>  - aslave needs to be closed when login_pty() failed

I'll fix that.


>  - login_pty() and dup2() used together

That's correct, expected, on purpose.


>  - aslave should be closed in parent

Like closefd(aslave) which my patch does?

Hi.

> Do you have any other idea?

Yes, we create a shared library which calls setbuf(stderr/out, NULL) in
an __attribute__((constructor)) function, then specify this library in
LD_PRELOAD when exec'ing stdio-relay enabled processes from procd.

This is equivalent to the implementation used by the coreutils "stdbuf"
applet.

~ Jow

On Jun 19, 2015 9:16 PM, "Rafał Miłecki" <zajec5@gmail.com> wrote:
>
> On 19 June 2015 at 14:44, Yousong Zhou <yszhou4tech@gmail.com> wrote:
> > On 19 June 2015 at 19:34, Rafał Miłecki <zajec5@gmail.com> wrote:
> >> Using pipe automatically switches service to block buffering which kind
> >> of breaks our logging. We won't get anything from FD until the buffer
> >> gets filled fully or the service exits. This makes log messages appear
> >> with an unwanted delay.
> >> Switching to PTY fixes this issue. Service prints to the "standard"
> >> stdout (no piping) but the messages go (line buffered) to the master FD
> >> anyway.
> >> It was successfully tested with all 4 variants of "stdout" and "stderr"
> >> ubus arguments.
> >>
> >
> > I do not like this because
> >
> >  - Conventionally, services will drop their inherited controlling
> > terminal for preparation of becoming a daemon.  Adding back that
> > controlling terminal by login_tty() for alleviating possible delay
> > when logging stdio sounds not right.
>
> Do you have any other idea?
> The delay isn't "possible", I think it occurs with 90%+ of apps. I'm
> not aware of many apps (except for grep maybe) that calls "fflush"
> after every printf. It simply makes reading real-time logs with
> "logread" not working at all.
>
>
> >  - I am biased... in that the ossherd [1] package depends on the fact
> > processes started by procd do not have controlling terminals and this
> > will unattended password login with ssh  :)
>
> I'm afraid I don't understand this part. In any case, you don't have
> to use logging in your init.d script. It's an option.
>

It's a hacky init script trying to start SOCKS5 proxies with
openssh-client.  Password authentication has to be used in this case.

>
> > Anyway, the implementation is not complete.
> >
> >  - epipe[] is still there.
>
> It is supposed to be. That's the only way to keep logging of stdout
> and stderr separated. Read my comment (in the code) about epipe.
>
>
> >  - aslave needs to be closed when login_pty() failed
>
> I'll fix that.
>
>
> >  - login_pty() and dup2() used together
>
> That's correct, expected, on purpose.
>

but login_pty will do dup2 on all 3 fd's with aslave.  it's duplicate work
and has side effects (regarding a pty stdin).

I think currently not many programs need procd_set_param stdout.  most of
the time if not always stderr, apart from syslog, is used for logging and
error reporting.  If that is agreed, then we can conclude that it is at
least a relatively rare case that we need to log stdout of the program, and
if that is the case we can afford and should patch the program itself to
use line buffered io with stdout.

Regards

                    yousong

>
> >  - aslave should be closed in parent
>
> Like closefd(aslave) which my patch does?

sorry, i missed that one before.