Skip to content

Commit c2a25ff

Browse files
committed
fix: address flushes that happen in the middle of a line
Simplify the logic around capturing output from exec'd process. Swap the use of poll() with the more straightforward read() idiom in the (relatively simpler) stdout & stderr worker processes and add support for relaying lines received across multiple read() system calls. Also add test for testing lines received across multiple read calls. Also updated ANSI color palette and default colors.
1 parent 0c7d635 commit c2a25ff

12 files changed

+591
-536
lines changed

Makefile

+3
Original file line numberDiff line numberDiff line change
@@ -143,6 +143,9 @@ endef
143143

144144
$(foreach test,$(TESTS),$(eval $(call TEST_template)))
145145

146+
# The partial write test depends on the compiled tests/midline-flush binary.
147+
tests/midline-flush/run: tests/midline-flush
148+
146149
# Once tests are complete (and successful), remove test results.
147150
test:
148151
@rm -rf $(TESTTMPDIR)

README.md

+2-1
Original file line numberDiff line numberDiff line change
@@ -120,9 +120,10 @@ Invoke provided command and write its colorized, precise time-stamped output bot
120120
-d, --dark use color scheme suitable for dark backgrounds
121121
-b, --bold highlight stderr in bold text (with no color)
122122
-p, --plain disable all timestamps, ANSI color and highlighting
123-
-o, --outcolor color
123+
-f, --forcecolor enforce the use of color when not writing to a TTY
124124
-e, --errcolor color
125125
-t, --ts enable timestamps in all outputs
126+
-r, --relative display timestamps as relative offsets from start time (implies --ts)
126127
-h, --help print this help message
127128
-v, --version print version string
128129
--debug enable debugging

t3.c

+119-100
Original file line numberDiff line numberDiff line change
@@ -39,33 +39,37 @@
3939
#define BUFFER_SIZE 4096
4040

4141
// A few ANSI color codes, see https://materialui.co/colors
42-
#define ANSI_COLOR_INDIGO_400 "\033[38;5;99m"
43-
#define ANSI_COLOR_INDIGO_300 "\033[38;5;141m"
44-
#define ANSI_COLOR_YELLOW_400 "\033[38;5;214m"
45-
#define ANSI_COLOR_YELLOW_300 "\033[38;5;220m"
46-
#define ANSI_COLOR_AMBER_400 "\033[38;5;130m"
47-
#define ANSI_COLOR_AMBER_300 "\033[38;5;166m"
48-
#define ANSI_COLOR_ORANGE_400 "\033[38;5;166m"
49-
#define ANSI_COLOR_ORANGE_300 "\033[38;5;130m"
50-
#define ANSI_BOLD "\033[1m"
51-
#define ANSI_RESET "\033[0m"
42+
#define ANSI_COLOR_RESET "\x1b[0m"
43+
#define ANSI_COLOR_BOLD "\x1b[1m"
44+
#define ANSI_COLOR_BLACK "\x1b[30m"
45+
#define ANSI_COLOR_RED "\x1b[31m"
46+
#define ANSI_COLOR_GREEN "\x1b[32m"
47+
#define ANSI_COLOR_YELLOW "\x1b[33m"
48+
#define ANSI_COLOR_BLUE "\x1b[34m"
49+
#define ANSI_COLOR_MAGENTA "\x1b[35m"
50+
#define ANSI_COLOR_CYAN "\x1b[36m"
51+
#define ANSI_COLOR_WHITE "\x1b[37m"
5252

5353
// Global variables
5454
int color_to_tty = 1;
5555
int debuglevel = 0;
5656
int timestamp_enabled = 0;
5757
int relative_timestamps = 0;
58-
const char *ts_color = ANSI_COLOR_INDIGO_300; // Timestamp color
59-
const char *reset_color = ANSI_RESET;
58+
const char *ts_color = ANSI_COLOR_CYAN; // Timestamp color
59+
const char *reset_color = ANSI_COLOR_RESET;
6060
struct timespec start_timestamp;
6161

6262
#define _debug(dlevel, format, ...) \
6363
if (debuglevel && debuglevel >= dlevel) \
64-
fprintf(stderr, "DEBUG[%d]: " format "\n", getpid(), ##__VA_ARGS__)
64+
fprintf(stderr, ANSI_COLOR_GREEN "DEBUG[%d]: " ANSI_COLOR_RESET format "\n", \
65+
getpid(), ##__VA_ARGS__)
6566
#define _warn(format, ...) \
66-
fprintf(stderr, "WARNING[%d]: " format "\n", getpid(), ##__VA_ARGS__)
67+
fprintf(stderr, \
68+
ANSI_COLOR_YELLOW "WARNING[%d]: " ANSI_COLOR_RESET format "\n", \
69+
getpid(), ##__VA_ARGS__)
6770
#define _error(format, ...) \
68-
fprintf(stderr, "ERROR[%d]: " format "\n", getpid(), ##__VA_ARGS__)
71+
fprintf(stderr, ANSI_COLOR_RED "ERROR[%d]: " ANSI_COLOR_RESET format "\n", \
72+
getpid(), ##__VA_ARGS__)
6973

7074
struct payload {
7175
struct timespec timestamp;
@@ -106,7 +110,7 @@ static void usage(const int rc) {
106110
printf(" -e, --errcolor color\n");
107111
printf(" -t, --ts "
108112
"enable timestamps in all outputs\n");
109-
printf(" -r, --relative "
113+
printf(" -r, --relative "
110114
"display timestamps as relative offsets from start time "
111115
"(implies --ts)\n");
112116
printf(" -h, --help print this help message\n");
@@ -115,13 +119,66 @@ static void usage(const int rc) {
115119
exit(rc);
116120
}
117121

122+
void send_msg_payload(int pipe_fd, struct payload *msg_payload) {
123+
// Send message payload to parent process being careful to
124+
// ensure that the entire message is sent.
125+
_debug(1, "Sending msg_payload '%s' to parent process, timestamp: %ld.%09ld",
126+
msg_payload->text, msg_payload->timestamp.tv_sec,
127+
msg_payload->timestamp.tv_nsec);
128+
ssize_t written = write(pipe_fd, msg_payload, sizeof(*msg_payload));
129+
while (written < sizeof(*msg_payload)) {
130+
if (written == -1) {
131+
if (errno == EAGAIN) {
132+
// If the pipe is full, keep trying to write
133+
// until it is available
134+
usleep(1000);
135+
written = write(pipe_fd, msg_payload, sizeof(*msg_payload));
136+
} else {
137+
perror("Error writing to pipe");
138+
break;
139+
}
140+
} else {
141+
// If only part of the message was written,
142+
// try again to write the rest of it
143+
ssize_t more_written =
144+
write(pipe_fd, msg_payload + written, sizeof(*msg_payload) - written);
145+
if (more_written == -1) {
146+
if (errno == EAGAIN) {
147+
// If the pipe is full, keep trying to write
148+
// until it is available
149+
while (more_written == -1 && errno == EAGAIN) {
150+
usleep(1000);
151+
more_written = write(pipe_fd, msg_payload + written,
152+
sizeof(*msg_payload) - written);
153+
}
154+
break;
155+
} else {
156+
perror("Error writing to pipe");
157+
break;
158+
}
159+
}
160+
written += more_written;
161+
}
162+
}
163+
}
164+
118165
void timestamp_and_send(int pipe_fd, int fd, const char *prefix) {
119166
char buffer[BUFFER_SIZE];
120-
struct pollfd pfd = {.fd = fd, .events = POLLIN | POLLHUP};
121-
struct payload msg_payload;
167+
ssize_t bytes_read;
168+
size_t line_length = 0;
122169

123170
// TODO: set argv[0] to incorporate prefix
124171

172+
// Set the read-side file descriptor to line-buffered mode using setvbuf
173+
FILE *stream = fdopen(fd, "r");
174+
if (!stream) {
175+
perror("fdopen failed");
176+
exit(EXIT_FAILURE);
177+
}
178+
setvbuf(stream, NULL, _IOLBF, 0); // Line buffering
179+
180+
struct payload msg_payload;
181+
125182
// Set pipe_fd to non-blocking mode
126183
int flags = fcntl(pipe_fd, F_GETFL, 0);
127184
if (flags == -1 || fcntl(pipe_fd, F_SETFL, flags | O_NONBLOCK) == -1) {
@@ -140,87 +197,48 @@ void timestamp_and_send(int pipe_fd, int fd, const char *prefix) {
140197
exit(EXIT_FAILURE);
141198
}
142199

143-
while (1) {
144-
int poll_result = poll(&pfd, 1, -1);
145-
if (poll_result == -1) {
146-
if (errno == EINTR)
147-
continue;
148-
perror("Error polling pipe");
149-
break;
150-
}
151-
152-
if (pfd.revents & POLLHUP) {
153-
// Pipe has been closed, exit the loop
154-
break;
200+
while ((bytes_read = read(fd, buffer, sizeof(buffer) - 1)) > 0) {
201+
// Get the current time with nanosecond precision. Note that if a
202+
// line is split across multiple reads, the timestamp will be set
203+
// to the time that the _last_ read is completed.
204+
if (clock_gettime(CLOCK_REALTIME, &msg_payload.timestamp) == -1) {
205+
perror("clock_gettime");
206+
exit(EXIT_FAILURE);
155207
}
156208

157-
if (pfd.revents & POLLIN) {
158-
ssize_t count = read(fd, buffer, BUFFER_SIZE - 1);
159-
if (count == 0) {
160-
// EOF detected, exit the loop
161-
break;
162-
}
163-
if (count < 0) {
164-
if (errno == EINTR)
165-
continue;
166-
perror("Error reading from pipe");
167-
break;
209+
buffer[bytes_read] = '\0'; // Null-terminate the buffer
210+
_debug(1, "Read %ld bytes from fd: '%s' timestamp: %ld.%09ld", bytes_read,
211+
buffer, msg_payload.timestamp.tv_sec, msg_payload.timestamp.tv_nsec);
212+
213+
size_t i = 0;
214+
while (i < bytes_read) {
215+
if (line_length >= BUFFER_SIZE - 1) {
216+
fprintf(stderr, "Line too long, truncating.\n");
217+
msg_payload.text[BUFFER_SIZE - 1] = '\0';
218+
send_msg_payload(pipe_fd, &msg_payload);
219+
line_length = 0;
168220
}
169221

170-
buffer[count] = '\0';
171-
char *line = strtok(buffer, "\n");
172-
while (line) {
173-
// Get the current time with nanosecond precision
174-
if (clock_gettime(CLOCK_REALTIME, &msg_payload.timestamp) == -1) {
175-
perror("clock_gettime");
176-
exit(EXIT_FAILURE);
177-
}
178-
179-
// Copy the line into the payload
180-
snprintf(msg_payload.text, BUFFER_SIZE, "%s", line);
181-
182-
// Send message to parent process being careful to ensure
183-
// that the entire message is sent.
184-
ssize_t written = write(pipe_fd, &msg_payload, sizeof(msg_payload));
185-
while (written < sizeof(msg_payload)) {
186-
if (written == -1) {
187-
if (errno == EAGAIN) {
188-
// If the pipe is full, keep trying to write
189-
// until it is available
190-
usleep(1000);
191-
written = write(pipe_fd, &msg_payload, sizeof(msg_payload));
192-
} else {
193-
perror("Error writing to pipe");
194-
break;
195-
}
196-
} else {
197-
// If only part of the message was written,
198-
// try again to write the rest of it
199-
ssize_t more_written = write(pipe_fd, &msg_payload + written,
200-
sizeof(msg_payload) - written);
201-
if (more_written == -1) {
202-
if (errno == EAGAIN) {
203-
// If the pipe is full, keep trying to write
204-
// until it is available
205-
while (more_written == -1 && errno == EAGAIN) {
206-
usleep(1000);
207-
more_written = write(pipe_fd, &msg_payload + written,
208-
sizeof(msg_payload) - written);
209-
}
210-
break;
211-
} else {
212-
perror("Error writing to pipe");
213-
break;
214-
}
215-
}
216-
written += more_written;
217-
}
218-
}
219-
220-
line = strtok(NULL, "\n");
222+
if (buffer[i] == '\n') {
223+
msg_payload.text[line_length] = '\0';
224+
send_msg_payload(pipe_fd, &msg_payload);
225+
line_length = 0; // Reset for the next line
226+
} else {
227+
msg_payload.text[line_length++] = buffer[i];
221228
}
229+
i++;
222230
}
223231
}
232+
233+
if (bytes_read < 0) {
234+
fprintf(stderr, "Error reading file descriptor: %s\n", strerror(errno));
235+
}
236+
237+
// Handle any remaining data in the buffer that doesn't end with a newline
238+
if (line_length > 0) {
239+
msg_payload.text[line_length] = '\0';
240+
send_msg_payload(pipe_fd, &msg_payload);
241+
}
224242
}
225243

226244
int timespec_cmp(const struct timespec *a, const struct timespec *b) {
@@ -326,8 +344,9 @@ int main(int argc, char *argv[]) {
326344
int opt;
327345
int option_index = 0;
328346
const char *logfile_name = NULL;
329-
const char *out_color = ""; // No color for stdout
330-
const char *err_color = ANSI_BOLD ANSI_COLOR_AMBER_400; // Default for stderr
347+
const char *out_color = ""; // No color for stdout
348+
const char *err_color =
349+
ANSI_COLOR_BOLD ANSI_COLOR_YELLOW; // Default for stderr
331350
int color_light = 0;
332351
int color_dark = 0;
333352
int color_bold = 0;
@@ -355,18 +374,18 @@ int main(int argc, char *argv[]) {
355374
&option_index)) != -1) {
356375
switch (opt) {
357376
case 'l':
358-
err_color = ANSI_BOLD ANSI_COLOR_AMBER_400; // for light background
359-
ts_color = ANSI_COLOR_INDIGO_400; // Timestamp color
377+
err_color = ANSI_COLOR_BOLD ANSI_COLOR_MAGENTA; // for light background
378+
ts_color = ANSI_COLOR_BLUE; // Timestamp color
360379
color_light = 1;
361380
break;
362381
case 'd':
363-
err_color = ANSI_BOLD ANSI_COLOR_YELLOW_300; // for dark background
364-
ts_color = ANSI_COLOR_INDIGO_300; // Timestamp color
382+
err_color = ANSI_COLOR_BOLD ANSI_COLOR_YELLOW; // for dark background
383+
ts_color = ANSI_COLOR_CYAN; // Timestamp color
365384
color_dark = 1;
366385
break;
367386
case 'b':
368-
err_color = ANSI_BOLD; // ANSI bold for stderr
369-
ts_color = ""; // Timestamp color
387+
err_color = ANSI_COLOR_BOLD; // ANSI bold for stderr
388+
ts_color = ""; // Timestamp color
370389
color_bold = 1;
371390
break;
372391
case 'f':

0 commit comments

Comments
 (0)