Статьи

Первичная причина регистрации исключений

Апрель 6, 2019
В версии 0.9.30 библиотеки журналов Logback появилась новая замечательная функция: трассировка стека журналов начинается с корневого (внутреннего) исключения, а не с самого внешнего. Конечно, мое волнение не имеет ничего общего с тем, что я внес эту функцию …

Перефразируя Сесила Б. де Милля: « Чтобы сделать пост в блоге, нужно начать с трассировки стека и довести до кульминации » — вот оно:

Детали пока не важны, но в режиме просмотра 100 футов вы можете увидеть трассировку длинного стека с несколькими исключениями, оборачивающими друг друга ( вызывая ). Мы вернемся к этой трассировке стека, но сначала некоторые основы. Если вы сгенерируете исключение, оно будет записано таким образом, чтобы показать, как выглядел стек в тот момент, когда возникло исключение. В самом низу вы увидите статические main () или Thread.run (), обработанные методами, вызываемыми до первой строки трассировки стека, указывающей место, где было выдано действительное исключение. Это очень удобно, так как вы можете увидеть весь поток управления, который привел к исключению:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
public class BookController {
 
  private final BookService bookService = new BookService();
 
  public void alpha() { beta(); }
 
  private void beta() { gamma(); }
 
  private void gamma() { bookService.delta(); }
 
  public static void main(String[] args) {
    new BookController().alpha();
  }
}
 
class BookService {
 
  private final BookDao bookDao = new BookDao();
 
  public void delta() { epsilon(); }
 
  private void epsilon() { zeta(); }
 
  private void zeta() { bookDao.eta(); }
}
 
class BookDao {
 
  public void eta() { theta(); }
 
  private void theta() { iota(); }
 
  public void iota() { throw new RuntimeException("Omega server not available"); }
}

Если вы не знаете греческий алфавит , вы можете начать обучение по трассировке стека (помните, что поток управления начинается снизу и идет вверх):

01
02
03
04
05
06
07
08
09
10
11
java.lang.RuntimeException: Omega server not available
  at BookDao.iota(BookController.java:50)
  at BookDao.theta(BookController.java:48)
  at BookDao.eta(BookController.java:46)
  at BookService.zeta(BookController.java:41)
  at BookService.epsilon(BookController.java:39)
  at BookService.delta(BookController.java:37)
  at BookController.gamma(BookController.java:22)
  at BookController.beta(BookController.java:20)
  at BookController.alpha(BookController.java:18)
  at BookController.main(BookController.java:26)

Замечательно, правда? При чтении сверху вниз вы можете сказать: iota () была вызвана theta () была вызвана eta ()… Ясно и просто. Однако что, если кто-то решит обернуть оригинальное исключение и повторно его выбросить?

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
public class BookController {
 
  private static final Logger log = LoggerFactory.getLogger(BookController.class);
 
  private final BookService bookService = new BookService();
 
  public void alpha() { beta(); }
 
  private void beta() { gamma(); }
 
  private void gamma() {
    try {
      bookService.delta();
    } catch (Exception e) {
      throw new RuntimeException("Sorry, try again later", e);
    }
  }
 
  public static void main(String[] args) {
    try {
      new BookController().alpha();
    } catch (Exception e) {
      log.error("", e);
    }
  }
}
 
class BookService {
 
  private final BookDao bookDao = new BookDao();
 
  public void delta() { epsilon(); }
 
  private void epsilon() { zeta(); }
 
  private void zeta() {
    try {
      bookDao.eta();
    } catch (Exception e) {
      throw new RuntimeException("Unable to save order", e);
    }
  }
}
 
class BookDao {
 
  public void eta() { theta(); }
 
  private void theta() { iota(); }
 
  public void iota() {
    try {
      throw new RuntimeException("Omega server not available");
    } catch (Exception e) {
      throw new RuntimeException("Database problem", e);
    }
  }
}

Теперь быстро: найдите основную причину в трассировке стека!

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
java.lang.RuntimeException: Sorry, try again later
  at BookController.gamma(BookController.java:26)
  at BookController.beta(BookController.java:20)
  at BookController.alpha(BookController.java:18)
  at BookController.main(BookController.java:32)
Caused by: java.lang.RuntimeException: Unable to save order
  at BookService.zeta(BookController.java:51)
  at BookService.epsilon(BookController.java:45)
  at BookService.delta(BookController.java:43)
  at BookController.gamma(BookController.java:24)
  ... 8 common frames omitted
Caused by: java.lang.RuntimeException: Database problem
  at BookDao.iota(BookController.java:66)
  at BookDao.theta(BookController.java:60)
  at BookDao.eta(BookController.java:58)
  at BookService.zeta(BookController.java:49)
  ... 11 common frames omitted
Caused by: java.lang.RuntimeException: Omega server not available
  at BookDao.iota(BookController.java:64)
  ... 14 common frames omitted

Оказывается, что main () больше не последняя строка. Хуже того, все кажется искаженным, попробуйте снова прочитать греческий алфавит … Теперь давайте вернемся к нашей первоначальной трассировке стека. Это происходит из-за сбоя запуска Spring Framework, представьте, что это может быть несколько страниц.

Для вашего удобства я добавил стрелки, чтобы обозначить путь, по которому вы должны следовать, чтобы восстановить поток управления: начиная с хвоста красной стрелки ( Thread.run () ) где-то посередине вы поднимаетесь, а затем… прыгаете к хвосту оранжевой стрелки , С головы оранжевой стрелки ты прыгаешь на хвост зеленой и так далее … Не очень интуитивно понятно, тебе не кажется? И что показывает этот красный эллипс? Да, это основная причина сбоя (самое внутреннее исключение). С другой стороны, исключение, напечатанное в самом начале (то, которое вы обычно читаете на первом месте), что-то говорит об ошибке при создании DefaultAnnotationHandlerMapping # 0 (что?) Истинная ошибка ( Нет подходящего компонента типа… ) скрыто скрыта…

Так что же это за новая функция ? Опять наш простой пример. После обновления до 0.9.30 просто добавьте % rEx (или эквивалентное % rootException ) в конце вашего шаблона регистрации:

1
2
3
4
5
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  <encoder>
    <pattern>%d{ISO8601} | %-5level | %thread | %logger{1} | %m%n%rEx</pattern>
  </encoder>
</appender>

Это заменит стандартную маршрутизацию печати трассировки стека на ту, которую я смиренно внес. Теперь та же греческая программа напечатает:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
java.lang.RuntimeException: Omega server not available
  at BookDao.iota(BookController.java:64)
Wrapped by: java.lang.RuntimeException: Database problem
  at BookDao.iota(BookController.java:66)
  at BookDao.theta(BookController.java:60)
  at BookDao.eta(BookController.java:58)
  at BookService.zeta(BookController.java:49)
Wrapped by: java.lang.RuntimeException: Unable to save order
  at BookService.zeta(BookController.java:51)
  at BookService.epsilon(BookController.java:45)
  at BookService.delta(BookController.java:43)
  at BookController.gamma(BookController.java:24)
Wrapped by: java.lang.RuntimeException: Sorry, try again later
  at BookController.gamma(BookController.java:26)
  at BookController.beta(BookController.java:20)
  at BookController.alpha(BookController.java:18)
  at BookController.main(BookController.java:32)

Пожалуйста, сравните это внимательно с предыдущим выводом. Прежде всего, самая первая строка указывает на проблему. Не копайтесь в исключениях « вызвано », большую часть времени вы, вероятно, пропустите остальные. Во-вторых, поток управления непрерывен и непрерывен — вы все равно можете читать его сверху вниз или наоборот. И последнее по порядку, но не по значению — тот факт, что исключения были перенесены в это время, сохраняется, но не искажает трассировку стека.

Теперь вы заслуживаете того, чтобы исходное исключение Spring использовало преимущества печати% rEx:

Наблюдения точно такие же: первопричина проблемы возникает в самом начале, сокращая время, необходимое для исследования проблемы. Также при анализе потока управления нет скачков — Thread.main () находится внизу, и вы можете непрерывно читать трассировку снизу вверх.

Если вы много «работаете» со следами стека (либо в разработке, либо в производстве / поддержке) — подумайте о переходе на первопричину в первую очередь. Это сэкономит вам несколько секунд каждый раз, когда вы анализируете конкретное исключение. Но я также заметил, что неопытные разработчики иногда даже не знают о правиле « Причины »: найдите первое исключение и посмотрите на последнее «Причинено» — оставаясь не понимающими, в чем заключается проблема, глядя только на самую внешнюю, наименее конкретную, наиболее общую ошибку. Это также поможет им.

Кстати — всей этой суеты можно избежать, если вы вообще избежите оборачивания и повторного выброса исключения. Я знаю, слишком часто мы вынуждены делать это по проверенным исключениям …

Ссылки: Первичная причина регистрации исключений — сначала от нашего партнера по JCG Томека Нуркевича в NoBlogDefFound

Удачного кодирования! Не забудь поделиться!

Статьи по Теме:

38
Share: