[1/3] utils: add read_lines_notify helper

Move the 'read lines and print to trace/error' logic out of
run_system_cmd into its own helper.

Also fix a few problems, that could be illustrated with the following
script:
---
echo This line is over 256 in length: Lorem ipsum dolor sit amet, consectetur adipiscing elit. Pellentesque posuere sapien quis tempus rutrum. Suspendisse eu mauris tincidunt, aliquam nisl id, laoreet nunc. Curabitur sodales ex at lacus iaculis elementum. Nulla varius tellus at orci dictum et.

sleep 1

echo -n This line takes time to come...
sleep 1
echo Here it is.

sleep 1

echo -n Trailing data
---

problems:
 - long line was only printing an arbitrary later part, now print a full
buffer if we get one
 - lines weren't continuated over multiple read calls because the
variable was reinitialized when re-entering the read loop
 - trailing data was never printed

Signed-off-by: Dominique Martinet <dominique.martinet@atmark-techno.com>
---
 core/pctl.c    | 90 +++++++++++++++++---------------------------------
 core/util.c    | 51 ++++++++++++++++++++++++++++
 include/util.h |  2 ++
 3 files changed, 83 insertions(+), 60 deletions(-)

Hi Dominique,

On 05.03.21 06:39, Dominique Martinet wrote:
> Move the 'read lines and print to trace/error' logic out of
> run_system_cmd into its own helper.

This is a good idea - run_system_cmd() is a too long function and then 
difficult to be read.

> 
> Also fix a few problems, that could be illustrated with the following
> script:
> ---
> echo This line is over 256 in length: Lorem ipsum dolor sit amet, consectetur adipiscing elit. Pellentesque posuere sapien quis tempus rutrum. Suspendisse eu mauris tincidunt, aliquam nisl id, laoreet nunc. Curabitur sodales ex at lacus iaculis elementum. Nulla varius tellus at orci dictum et.
> 

Known, I simply considered unsupported if output is more as 256 bytes. 
Thanks for fixing this.

> sleep 1
> 
> echo -n This line takes time to come...
> sleep 1
> echo Here it is.
> 
> sleep 1
> 
> echo -n Trailing data
> ---
> 
> problems:
>   - long line was only printing an arbitrary later part, now print a full
> buffer if we get one
>   - lines weren't continuated over multiple read calls because the
> variable was reinitialized when re-entering the read loop
>   - trailing data was never printed
> 
> Signed-off-by: Dominique Martinet <dominique.martinet@atmark-techno.com>
> ---
>   core/pctl.c    | 90 +++++++++++++++++---------------------------------
>   core/util.c    | 51 ++++++++++++++++++++++++++++
>   include/util.h |  2 ++
>   3 files changed, 83 insertions(+), 60 deletions(-)
> 
> diff --git a/core/pctl.c b/core/pctl.c
> index 481f07773e11..ec21bbd9c8f4 100644
> --- a/core/pctl.c
> +++ b/core/pctl.c
> @@ -264,6 +264,9 @@ int run_system_cmd(const char *cmd)
>   	} else {
>   		int fds[2];
>   		pid_t w;
> +		char buf[2][SWUPDATE_GENERAL_STRING_SIZE];
> +		int cindex[2] = {0, 0}; /* this is the first free char inside buffer */
> +		LOGLEVEL levels[2] = { TRACELEVEL, ERRORLEVEL };
>   
>   		close(stdoutpipe[PIPE_WRITE]);
>   		close(stderrpipe[PIPE_WRITE]);
> @@ -271,6 +274,14 @@ int run_system_cmd(const char *cmd)
>   		fds[0] = stdoutpipe[PIPE_READ];
>   		fds[1] = stderrpipe[PIPE_READ];
>   
> +		/*
> +		 * Use buffers (for stdout and stdin) to collect data from
> +		 * the cmd. Data can contain multiple lines or just a part
> +		 * of a line and must be parsed
> +		 */
> +		memset(buf[0], 0, SWUPDATE_GENERAL_STRING_SIZE);
> +		memset(buf[1], 0, SWUPDATE_GENERAL_STRING_SIZE);
> +
>   		/*
>   		 * Now waits until the child process exits and checks
>   		 * for the output. Forward data from stdout as TRACE
> @@ -281,9 +292,6 @@ int run_system_cmd(const char *cmd)
>   			struct timeval tv;
>   			fd_set readfds;
>   			int n, i;
> -			char buf[2][SWUPDATE_GENERAL_STRING_SIZE];
> -			char *pbuf;
> -			int cindex[2] = {0, 0}; /* this is the first free char inside buffer */
>   
>   			w = waitpid(process_id, &wstatus, WNOHANG | WUNTRACED | WCONTINUED);
>   			if (w == -1) {
> @@ -293,14 +301,6 @@ int run_system_cmd(const char *cmd)
>   				return -EFAULT;
>   			}
>   
> -			/*
> -			 * Use buffers (for stdout and stdin) to collect data from
> -			 * the cmd. Data can contain multiple lines or just a part
> -			 * of a line and must be parsed
> -			 */
> -			memset(buf[0], 0, SWUPDATE_GENERAL_STRING_SIZE);
> -			memset(buf[1], 0, SWUPDATE_GENERAL_STRING_SIZE);
> -
>   			tv.tv_sec = 1;
>   			tv.tv_usec = 0;
>   
> @@ -316,65 +316,35 @@ int run_system_cmd(const char *cmd)
>   					break;
>   
>   				for (i = 0; i < 2 ; i++) {
> -					pbuf = buf[i];
> -					int c = cindex[i];
> +					char *pbuf = buf[i];
> +					int *c = &cindex[i];
> +					LOGLEVEL level = levels[i];
>   
>   					if (FD_ISSET(fds[i], &readfds)) {
> -						int last;
> -
> -						n = read(fds[i], &pbuf[c], SWUPDATE_GENERAL_STRING_SIZE - c);
> +						n = read_lines_notify(fds[i], pbuf, SWUPDATE_GENERAL_STRING_SIZE,
> +								      c, level);
>   						if (n < 0)
>   							continue;
> -						n += c;	/* add previous data, if any */
>   						n1 += n;
> -						if (n > 0) {
> -
> -							/* check if just a part of a line was sent. In that
> -							 * case, search for the last line and then copy the rest
> -							 * to the begin of the buffer for next read
> -							 */
> -							last = n - 1;
> -							while (last > 0 && pbuf[last] != '\0' && pbuf[last] != '\n')
> -									last--;
> -							pbuf[last] = '\0';
> -							/*
> -							 * compute the truncate line that should be
> -							 * parsed next time when the rest is received
> -							 */
> -							int left = n - 1 - last;
> -							char **lines = string_split(pbuf, '\n');
> -							int nlines = count_string_array((const char **)lines);
> -
> -							if (last < SWUPDATE_GENERAL_STRING_SIZE - 1) {
> -								last++;
> -								memcpy(pbuf, &pbuf[last], left);
> -								if (last + left < SWUPDATE_GENERAL_STRING_SIZE) {
> -									memset(&pbuf[left], 0, SWUPDATE_GENERAL_STRING_SIZE - left);
> -								}
> -								cindex[i] = left;
> -							} else { /* no need to copy, reuse all buffer */
> -								memset(pbuf, 0, SWUPDATE_GENERAL_STRING_SIZE);
> -								cindex[i] = 0;
> -							}
> -
> -							for (unsigned int index = 0; index < nlines; index++) {
> -								switch (i) {
> -								case 0:
> -									TRACE("%s", lines[index]);
> -									break;
> -								case 1:
> -									ERROR("%s", lines[index]);
> -									break;
> -								}
> -							}
> -
> -							free_string_array(lines);
> -						}
>   					}
>   				}
>   			} while (ret > 0 && n1 > 0);
>   		} while (w != process_id);
>   
> +		/* print any unfinished line */
> +		for (int i = 0; i < 2; i++) {
> +			if (cindex[i]) {
> +				switch(i) {
> +				case 0:
> +					TRACE("%s", buf[i]);
> +					break;
> +				case 1:
> +					ERROR("%s", buf[i]);
> +					break;
> +				}
> +			}
> +		}
> +
>   		close(stdoutpipe[PIPE_READ]);
>   		close(stderrpipe[PIPE_READ]);
>   
> diff --git a/core/util.c b/core/util.c
> index 2025276445dd..0ee536f4b8a7 100644
> --- a/core/util.c
> +++ b/core/util.c
> @@ -842,3 +842,54 @@ size_t snescape(char *dst, size_t n, const char *src)
>   
>   	return len;
>   }
> +
> +int read_lines_notify(int fd, char *buf, int buf_size, int *buf_offset,
> +		      LOGLEVEL level)
> +{
> +	int n;
> +	int offset = *buf_offset;
> +	int print_last = 0;
> +
> +	n = read(fd, &buf[offset], buf_size - offset - 1);
> +	if (n <= 0)
> +		return -errno;
> +
> +	n += offset;
> +	buf[n] = '\0';
> +
> +	/*
> +	 * Check if last line was finished, or if we should copy
> +	 * it back for next call.
> +	 * If the buffer is full and there is only one line it
> +	 * will be printed anyway
> +	 */
> +	if (buf[n-1] == '\n') {
> +		print_last = 1;
> +	}

This is not clear to me - what I did in current pctl code, is to scan 
the buffer from last char to find a terminating linefeed. You just check 
the last char - how can we be sure that the read is synchronized, and 
the buffer does not contain the last part of a line and the first part 
of the next one ?

I mean : buf could be
	<c0><c1>....<cn>\n<d0><d1>...<di>

> +
> +	char **lines = string_split(buf, '\n');
> +	int nlines = count_string_array((const char **)lines);
> +	if (n >= buf_size - 1 && nlines == 1)
> +		print_last = 1;
> +
> +	/* copy leftover data for next call */
> +	if (!print_last) {
> +		int left = snprintf(buf, buf_size, "%s", lines[nlines-1]);
> +		memset(&buf[left], 0, SWUPDATE_GENERAL_STRING_SIZE - left);

I guess zeroing the read part of the buffer is redundant, is not it ? 
The marker is buf_offset.

> +		*buf_offset = left;
> +		nlines--;
> +		n -= left;
> +	} else { /* no need to copy, reuse all buffer */
> +		memset(buf, 0, n);

Ditto.

> +		*buf_offset = 0;
> +	}
> +
> +	for (unsigned int index = 0; index < nlines; index++) {
> +		RECOVERY_STATUS status = level == ERRORLEVEL ? FAILURE : RUN;
> +		swupdate_notify(status, "%s", level, lines[index]);
> +	}
> +
> +	free_string_array(lines);
> +
> +	return n;
> +}
> diff --git a/include/util.h b/include/util.h
> index ad2e90cabd12..76448504f303 100644
> --- a/include/util.h
> +++ b/include/util.h
> @@ -216,6 +216,8 @@ int check_hw_compatibility(struct swupdate_cfg *cfg);
>   int count_elem_list(struct imglist *list);
>   unsigned int count_string_array(const char **nodes);
>   void free_string_array(char **nodes);
> +int read_lines_notify(int fd, char *buf, int buf_size, int *buf_offset,
> +		      LOGLEVEL level);
>   
>   /* Decryption key functions */
>   int load_decryption_key(char *fname);
> 

Best regards,
Stefano Babic

Stefano Babic wrote on Sat, Mar 06, 2021 at 10:32:27AM +0100:
> > +	/*
> > +	 * Check if last line was finished, or if we should copy
> > +	 * it back for next call.
> > +	 * If the buffer is full and there is only one line it
> > +	 * will be printed anyway
> > +	 */
> > +	if (buf[n-1] == '\n') {
> > +		print_last = 1;
> > +	}
> 
> This is not clear to me - what I did in current pctl code, is to scan the
> buffer from last char to find a terminating linefeed. You just check the
> last char - how can we be sure that the read is synchronized, and the buffer
> does not contain the last part of a line and the first part of the next one
> ?
> 
> I mean : buf could be
> 	<c0><c1>....<cn>\n<d0><d1>...<di>

That is precisely what the above check (is the last char a line return)
brings.

The key here is that string_split uses strtok, which will always return
the last component of the buffer wether there is a trailing new line or
not -- in its split state, there is no way of making the difference
between these two buffers:
  "one line\ntwo lines\n"
  "one line\ntwo lines" -- that one is not terminated

By checking beforehand if the last character is a line feed the code
decides later if the last element of the split should be print or copied
back to the start of the buffer.

As for going back to look for earlier new line characters if the last
one wasn't, this can be decided based on the string_split output as done
just below:
> > +
> > +	char **lines = string_split(buf, '\n');
> > +	int nlines = count_string_array((const char **)lines);
> > +	if (n >= buf_size - 1 && nlines == 1)
> > +		print_last = 1;

Here if nlines == 1 we know there was no \n before the last character,
so if the last character wasn't a \n already then there is none at all
and we're not printing unless the buffer is full.


I'm not sure how to make this clearer, would inverting the "print_last"
bool to "keep_last" or "copy_last" help hint that we're carrying on
leftover data to the start of the buffer?


> > +
> > +	/* copy leftover data for next call */
> > +	if (!print_last) {
> > +		int left = snprintf(buf, buf_size, "%s", lines[nlines-1]);
> > +		memset(&buf[left], 0, SWUPDATE_GENERAL_STRING_SIZE - left);
> 
> I guess zeroing the read part of the buffer is redundant, is not it ? The
> marker is buf_offset.

Yes, these are not needed in practice, as the code makes sure there is a
trailing \0 after the read data and snprintf preserves it -- I just kept
these are the orignal code was full of memsets, but the new code is now
far enough that I don't mind removing these.

Note that neither versions would support nul bytes in stdout/stderr
(data in a single read call after a nul byte would silently be dropped),
but since it goes to logging functions I don't think there would be any
reason of handling binary data.


I'll send a v2 without memsets after the line continuation check has
been cleared off