Commit 084681d14e429cb6192262ac7437f00e2c02f26a

Authored by Kay Sievers
Committed by Greg Kroah-Hartman
1 parent 116e90b23f

printk: flush continuation lines immediately to console

Continuation lines are buffered internally, intended to merge the
chunked printk()s into a single record, and to isolate potentially
racy continuation users from usual terminated line users.

This though, has the effect that partial lines are not printed to
the console in the moment they are emitted. In case the kernel
crashes in the meantime, the potentially interesting printed
information would never reach the consoles.

Here we share the continuation buffer with the console copy logic,
and partial lines are always immediately flushed to the available
consoles. They are still buffered internally to improve the
readability and integrity of the messages and minimize the amount
of needed record headers to store.

Signed-off-by: Kay Sievers <kay@vrfy.org>
Tested-by: Steven Rostedt <rostedt@goodmis.org>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

Showing 1 changed file with 176 additions and 68 deletions Side-by-side Diff

... ... @@ -193,12 +193,19 @@
193 193 * separated by ',', and find the message after the ';' character.
194 194 */
195 195  
  196 +enum log_flags {
  197 + LOG_DEFAULT = 0,
  198 + LOG_NOCONS = 1, /* already flushed, do not print to console */
  199 +};
  200 +
196 201 struct log {
197 202 u64 ts_nsec; /* timestamp in nanoseconds */
198 203 u16 len; /* length of entire record */
199 204 u16 text_len; /* length of text buffer */
200 205 u16 dict_len; /* length of dictionary buffer */
201   - u16 level; /* syslog level + facility */
  206 + u8 facility; /* syslog facility */
  207 + u8 flags:5; /* internal record flags */
  208 + u8 level:3; /* syslog level */
202 209 };
203 210  
204 211 /*
... ... @@ -286,6 +293,7 @@
286 293  
287 294 /* insert record into the buffer, discard old ones, update heads */
288 295 static void log_store(int facility, int level,
  296 + enum log_flags flags, u64 ts_nsec,
289 297 const char *dict, u16 dict_len,
290 298 const char *text, u16 text_len)
291 299 {
... ... @@ -329,8 +337,13 @@
329 337 msg->text_len = text_len;
330 338 memcpy(log_dict(msg), dict, dict_len);
331 339 msg->dict_len = dict_len;
332   - msg->level = (facility << 3) | (level & 7);
333   - msg->ts_nsec = local_clock();
  340 + msg->facility = facility;
  341 + msg->level = level & 7;
  342 + msg->flags = flags & 0x1f;
  343 + if (ts_nsec > 0)
  344 + msg->ts_nsec = ts_nsec;
  345 + else
  346 + msg->ts_nsec = local_clock();
334 347 memset(log_dict(msg) + dict_len, 0, pad_len);
335 348 msg->len = sizeof(struct log) + text_len + dict_len + pad_len;
336 349  
... ... @@ -446,7 +459,7 @@
446 459 ts_usec = msg->ts_nsec;
447 460 do_div(ts_usec, 1000);
448 461 len = sprintf(user->buf, "%u,%llu,%llu;",
449   - msg->level, user->seq, ts_usec);
  462 + (msg->facility << 3) | msg->level, user->seq, ts_usec);
450 463  
451 464 /* escape non-printable characters */
452 465 for (i = 0; i < msg->text_len; i++) {
... ... @@ -787,6 +800,21 @@
787 800 #endif
788 801 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
789 802  
  803 +static size_t print_time(u64 ts, char *buf)
  804 +{
  805 + unsigned long rem_nsec;
  806 +
  807 + if (!printk_time)
  808 + return 0;
  809 +
  810 + if (!buf)
  811 + return 15;
  812 +
  813 + rem_nsec = do_div(ts, 1000000000);
  814 + return sprintf(buf, "[%5lu.%06lu] ",
  815 + (unsigned long)ts, rem_nsec / 1000);
  816 +}
  817 +
790 818 static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
791 819 {
792 820 size_t len = 0;
... ... @@ -803,18 +831,7 @@
803 831 }
804 832 }
805 833  
806   - if (printk_time) {
807   - if (buf) {
808   - unsigned long long ts = msg->ts_nsec;
809   - unsigned long rem_nsec = do_div(ts, 1000000000);
810   -
811   - len += sprintf(buf + len, "[%5lu.%06lu] ",
812   - (unsigned long) ts, rem_nsec / 1000);
813   - } else {
814   - len += 15;
815   - }
816   - }
817   -
  834 + len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
818 835 return len;
819 836 }
820 837  
821 838  
... ... @@ -1294,15 +1311,92 @@
1294 1311 }
1295 1312 }
1296 1313  
  1314 +/*
  1315 + * Continuation lines are buffered, and not committed to the record buffer
  1316 + * until the line is complete, or a race forces it. The line fragments
  1317 + * though, are printed immediately to the consoles to ensure everything has
  1318 + * reached the console in case of a kernel crash.
  1319 + */
  1320 +static struct cont {
  1321 + char buf[LOG_LINE_MAX];
  1322 + size_t len; /* length == 0 means unused buffer */
  1323 + size_t cons; /* bytes written to console */
  1324 + struct task_struct *owner; /* task of first print*/
  1325 + u64 ts_nsec; /* time of first print */
  1326 + u8 level; /* log level of first message */
  1327 + u8 facility; /* log level of first message */
  1328 + bool flushed:1; /* buffer sealed and committed */
  1329 +} cont;
  1330 +
  1331 +static void cont_flush(void)
  1332 +{
  1333 + if (cont.flushed)
  1334 + return;
  1335 + if (cont.len == 0)
  1336 + return;
  1337 +
  1338 + log_store(cont.facility, cont.level, LOG_NOCONS, cont.ts_nsec,
  1339 + NULL, 0, cont.buf, cont.len);
  1340 +
  1341 + cont.flushed = true;
  1342 +}
  1343 +
  1344 +static bool cont_add(int facility, int level, const char *text, size_t len)
  1345 +{
  1346 + if (cont.len && cont.flushed)
  1347 + return false;
  1348 +
  1349 + if (cont.len + len > sizeof(cont.buf)) {
  1350 + cont_flush();
  1351 + return false;
  1352 + }
  1353 +
  1354 + if (!cont.len) {
  1355 + cont.facility = facility;
  1356 + cont.level = level;
  1357 + cont.owner = current;
  1358 + cont.ts_nsec = local_clock();
  1359 + cont.cons = 0;
  1360 + cont.flushed = false;
  1361 + }
  1362 +
  1363 + memcpy(cont.buf + cont.len, text, len);
  1364 + cont.len += len;
  1365 + return true;
  1366 +}
  1367 +
  1368 +static size_t cont_print_text(char *text, size_t size)
  1369 +{
  1370 + size_t textlen = 0;
  1371 + size_t len;
  1372 +
  1373 + if (cont.cons == 0) {
  1374 + textlen += print_time(cont.ts_nsec, text);
  1375 + size -= textlen;
  1376 + }
  1377 +
  1378 + len = cont.len - cont.cons;
  1379 + if (len > 0) {
  1380 + if (len+1 > size)
  1381 + len = size-1;
  1382 + memcpy(text + textlen, cont.buf + cont.cons, len);
  1383 + textlen += len;
  1384 + cont.cons = cont.len;
  1385 + }
  1386 +
  1387 + if (cont.flushed) {
  1388 + text[textlen++] = '\n';
  1389 + /* got everything, release buffer */
  1390 + cont.len = 0;
  1391 + }
  1392 + return textlen;
  1393 +}
  1394 +
1297 1395 asmlinkage int vprintk_emit(int facility, int level,
1298 1396 const char *dict, size_t dictlen,
1299 1397 const char *fmt, va_list args)
1300 1398 {
1301 1399 static int recursion_bug;
1302   - static char cont_buf[LOG_LINE_MAX];
1303   - static size_t cont_len;
1304   - static int cont_level;
1305   - static struct task_struct *cont_task;
1306 1400 static char textbuf[LOG_LINE_MAX];
1307 1401 char *text = textbuf;
1308 1402 size_t text_len;
... ... @@ -1348,7 +1442,8 @@
1348 1442 recursion_bug = 0;
1349 1443 printed_len += strlen(recursion_msg);
1350 1444 /* emit KERN_CRIT message */
1351   - log_store(0, 2, NULL, 0, recursion_msg, printed_len);
  1445 + log_store(0, 2, LOG_DEFAULT, 0,
  1446 + NULL, 0, recursion_msg, printed_len);
1352 1447 }
1353 1448  
1354 1449 /*
1355 1450  
1356 1451  
1357 1452  
1358 1453  
1359 1454  
... ... @@ -1386,55 +1481,38 @@
1386 1481 }
1387 1482  
1388 1483 if (!newline) {
1389   - if (cont_len && (prefix || cont_task != current)) {
1390   - /*
1391   - * Flush earlier buffer, which is either from a
1392   - * different thread, or when we got a new prefix.
1393   - */
1394   - log_store(facility, cont_level, NULL, 0, cont_buf, cont_len);
1395   - cont_len = 0;
1396   - }
  1484 + /*
  1485 + * Flush the conflicting buffer. An earlier newline was missing,
  1486 + * or another task also prints continuation lines.
  1487 + */
  1488 + if (cont.len && (prefix || cont.owner != current))
  1489 + cont_flush();
1397 1490  
1398   - if (!cont_len) {
1399   - cont_level = level;
1400   - cont_task = current;
1401   - }
1402   -
1403   - /* buffer or append to earlier buffer from the same thread */
1404   - if (cont_len + text_len > sizeof(cont_buf))
1405   - text_len = sizeof(cont_buf) - cont_len;
1406   - memcpy(cont_buf + cont_len, text, text_len);
1407   - cont_len += text_len;
  1491 + /* buffer line if possible, otherwise store it right away */
  1492 + if (!cont_add(facility, level, text, text_len))
  1493 + log_store(facility, level, LOG_DEFAULT, 0,
  1494 + dict, dictlen, text, text_len);
1408 1495 } else {
1409   - if (cont_len && cont_task == current) {
1410   - if (prefix) {
1411   - /*
1412   - * New prefix from the same thread; flush. We
1413   - * either got no earlier newline, or we race
1414   - * with an interrupt.
1415   - */
1416   - log_store(facility, cont_level,
1417   - NULL, 0, cont_buf, cont_len);
1418   - cont_len = 0;
1419   - }
  1496 + bool stored = false;
1420 1497  
1421   - /* append to the earlier buffer and flush */
1422   - if (cont_len + text_len > sizeof(cont_buf))
1423   - text_len = sizeof(cont_buf) - cont_len;
1424   - memcpy(cont_buf + cont_len, text, text_len);
1425   - cont_len += text_len;
1426   - log_store(facility, cont_level,
1427   - NULL, 0, cont_buf, cont_len);
1428   - cont_len = 0;
1429   - cont_task = NULL;
1430   - printed_len = cont_len;
1431   - } else {
1432   - /* ordinary single and terminated line */
1433   - log_store(facility, level,
1434   - dict, dictlen, text, text_len);
1435   - printed_len = text_len;
  1498 + /*
  1499 + * Flush the conflicting buffer. An earlier newline was missing,
  1500 + * or we race with a continuation line from an interrupt.
  1501 + */
  1502 + if (cont.len && prefix && cont.owner == current)
  1503 + cont_flush();
  1504 +
  1505 + /* Merge with our buffer if possible; flush it in any case */
  1506 + if (cont.len && cont.owner == current) {
  1507 + stored = cont_add(facility, level, text, text_len);
  1508 + cont_flush();
1436 1509 }
  1510 +
  1511 + if (!stored)
  1512 + log_store(facility, level, LOG_DEFAULT, 0,
  1513 + dict, dictlen, text, text_len);
1437 1514 }
  1515 + printed_len += text_len;
1438 1516  
1439 1517 /*
1440 1518 * Try to acquire and then immediately release the console semaphore.
1441 1519  
... ... @@ -1521,11 +1599,18 @@
1521 1599 #else
1522 1600  
1523 1601 #define LOG_LINE_MAX 0
  1602 +static struct cont {
  1603 + size_t len;
  1604 + size_t cons;
  1605 + u8 level;
  1606 + bool flushed:1;
  1607 +} cont;
1524 1608 static struct log *log_from_idx(u32 idx) { return NULL; }
1525 1609 static u32 log_next(u32 idx) { return 0; }
1526 1610 static void call_console_drivers(int level, const char *text, size_t len) {}
1527 1611 static size_t msg_print_text(const struct log *msg, bool syslog,
1528 1612 char *buf, size_t size) { return 0; }
  1613 +static size_t cont_print_text(char *text, size_t size) { return 0; }
1529 1614  
1530 1615 #endif /* CONFIG_PRINTK */
1531 1616  
... ... @@ -1817,6 +1902,7 @@
1817 1902 */
1818 1903 void console_unlock(void)
1819 1904 {
  1905 + static char text[LOG_LINE_MAX];
1820 1906 static u64 seen_seq;
1821 1907 unsigned long flags;
1822 1908 bool wake_klogd = false;
1823 1909  
... ... @@ -1829,10 +1915,23 @@
1829 1915  
1830 1916 console_may_schedule = 0;
1831 1917  
  1918 + /* flush buffered message fragment immediately to console */
  1919 + raw_spin_lock_irqsave(&logbuf_lock, flags);
  1920 + if (cont.len && (cont.cons < cont.len || cont.flushed)) {
  1921 + size_t len;
  1922 +
  1923 + len = cont_print_text(text, sizeof(text));
  1924 + raw_spin_unlock(&logbuf_lock);
  1925 + stop_critical_timings();
  1926 + call_console_drivers(cont.level, text, len);
  1927 + start_critical_timings();
  1928 + local_irq_restore(flags);
  1929 + } else
  1930 + raw_spin_unlock_irqrestore(&logbuf_lock, flags);
  1931 +
1832 1932 again:
1833 1933 for (;;) {
1834 1934 struct log *msg;
1835   - static char text[LOG_LINE_MAX];
1836 1935 size_t len;
1837 1936 int level;
1838 1937  
1839 1938  
1840 1939  
... ... @@ -1847,13 +1946,22 @@
1847 1946 console_seq = log_first_seq;
1848 1947 console_idx = log_first_idx;
1849 1948 }
1850   -
  1949 +skip:
1851 1950 if (console_seq == log_next_seq)
1852 1951 break;
1853 1952  
1854 1953 msg = log_from_idx(console_idx);
1855   - level = msg->level & 7;
  1954 + if (msg->flags & LOG_NOCONS) {
  1955 + /*
  1956 + * Skip record we have buffered and already printed
  1957 + * directly to the console when we received it.
  1958 + */
  1959 + console_idx = log_next(console_idx);
  1960 + console_seq++;
  1961 + goto skip;
  1962 + }
1856 1963  
  1964 + level = msg->level;
1857 1965 len = msg_print_text(msg, false, text, sizeof(text));
1858 1966  
1859 1967 console_idx = log_next(console_idx);