Observability Pt. 4: การเชื่อมความสัมพันธ์ระหว่าง Trace กับ Log

สวัสดีเพื่อน ๆ ผู้อ่านทุกท่านครับ หลังจากห่างหายกันไปนาน ก็กลับมาพบกันอีกครั้งกับซีรีย์ Observability นะครับ สำหรับบทความตอนนี้ เรายังอยู่ในเรื่องของ Trace เช่นเคย โดยจะเพิ่มไปแตะเรื่อง Log หน่อยนึง เรื่องที่ผมจะนำมาเขียนในวันนี้ก็คือวิธีการเชื่อมโยงข้อมูลระหว่าง Trace กับ Log นั่นเองครับ

ก่อนที่เราจะมาดูวิธีการเชื่อมความสัมพันธ์ระหว่าง Trace กับ Log ผมขอพาย้อนมาดูภาพรวมก่อนว่าความสามารถ Observability ที่ประกอบไปด้วย Log, Metric, และ Trace เนี่ย เราใช้งานร่วมกันยังไงครับ

Relationship between Log, Metric, and Trace

เริ่มต้นจาก Metric ที่เป็นการแสดงข้อมูลในรูปแบบ Dashboard ตรงนี้มักจะเป็นจุดแรกที่เราเข้ามาดู​ เวลาที่บริการของเรามีปัญหาอะไรเกิดขึ้น ปัญหาเหล่านั้นควรจะแสดงออกมาที่ Metric ให้เราสังเกตเห็นได้ก่อน เช่น TPS อาจจะลดลง, Response Time เพิ่มขึ้น, Error Rate เพิ่มขึ้น เป็นต้น (Detect)

พอเรารู้ว่าบริการของเรามีปัญหาจาก Metric แล้ว เราก็จะมาดูที่ Trace ซึ่งแสดงภาพแบบ End-to-end เป็นอันดับต่อไป ว่าปัญหาที่เกิดขึ้นนั้นเกิดขึ้นที่ ระบบไหน หรือส่วนประกอบตรงไหน หรือข้อต่อตรงไหนกันแน่ (Troubleshoot)

หลังจากที่รู้ว่าส่วนไหนของระบบไหนมีปัญหา เราก็มาดูที่ Log ซึ่งเป็นระดับที่ละเอียดที่สุดที่เราจะมีข้อมูล เราคาดหวังว่า Log น่าจะมีการเก็บพวก Request Parameter หรือ Error Message ต่าง ๆ ที่เกิดขึ้น เพื่อให้เรารู้ต้นตอที่แท้จริงของปัญหา (Pinpoint)

จะเห็นว่าข้อมูลทั้ง 3 อย่างนี้ต้องเชื่อมโยงถึงกันได้ใช่ไหมครับ เช่น เราดูข้อมูล Trace หนึ่งอยู่ ก็ควรจะต้องสามารถเชื่อมไปหา Log ของ Trace นั้น ๆ ได้ ในทำนองเดียวกัน ถ้าเราเปิด Log หนึ่งอยู่ แล้วอยากเห็นข้อมูลแบบ End-to-end ก็ควรเชื่อมไปหาข้อมูล Trace ได้เช่นกัน

ทีนี้ก่อนที่จะเชื่อมความสัมพันธ์ของ Trace กับ Log เราต้องมาดูก่อนว่าข้อมูลที่อยู่ใน Trace นั้นมีอะไรบ้าง

Trace คือข้อมูลของรายการหนึ่ง ๆ แบบ End-to-end ไม่ว่าการทำงานจะมีกี่ขั้นตอนก็ตาม ถัดลงมาจาก Trace จะเป็นสิ่งที่เรียกว่า Span ซึ่งก็คือขั้นตอนย่อย ๆ แต่ละขั้นตอนที่เราเห็นใน Trace นั่นเอง โดยขั้นตอนหนึ่ง ๆ ก็จะเป็น 1 Span แต่ละ Trace และ Span ก็จะมี ID ของตัวเองอยู่ที่ไม่ซ้ำกัน เรียกว่า Trace ID และ Span ID

Trace และ Span

ภายใน Span จะเก็บข้อมูลได้อีก 2 แบบ คือ

1. Span Attribute จะเก็บข้อมูลเป็นแบบ Key-Value โดยในแต่ละ Span จะมี Span Attribute ทั้งที่เป็น Default ที่ตัว Library ที่เราใช้บันทึกไว้ให้อยู่แล้ว และเราสามารถใส่เพิ่มเติมเข้าไปได้เองด้วยครับ
2. Span Event เก็บข้อมูลเป็น Text ใด ๆ ก็ได้ คล้าย ๆ กับ Log นอกจากนี้ในแต่ละ Span Event สามารถเก็บข้อมูลที่เป็นลักษณะ Key-Value เพิ่มเติมเข้าไปได้อีกด้วย

Span Attribute (Left) / Span Event (Right)

เอาล่ะครับ พอเรารู้แล้วว่าใน Trace ประกอบไปด้วยข้อมูลอะไร และเราเอาอะไรไปใส่ได้บ้าง ก็น่าจะพอเดาได้ว่าการเชื่อมความสัมพันธ์ระหว่าง Trace และ Log นั้น เราทำได้ 2 แบบ คือ

1. เอา Trace ID และ Span ID ไปใส่ใน Log
2. เอาข้อมูลบางอย่างที่เราเขียนใน Log มาใส่ใน Trace เป็น Span Attribute ตัวหนึ่ง

แบบนี้เราก็จะสามารถเชื่อมโยงข้อมูลไปมาระหว่างข้อมูลใน Trace และ Log โดยเพื่อน ๆ อาจจะเลือกทำทั้ง 2 อย่างหรือทำอย่างใดอย่างหนึ่งก็ได้

เพื่อให้เห็นภาพ เดี๋ยววันนี้เรามาลองทำสิ่งนี้กันดูจริง ๆ โดยใช้ OpenTelemetry เหมือนเดิม และโปรแกรมที่เราจะใช้เดโมในวันนี้ก็จะเป็น Spring-petclinic ตัวเดิมเช่นกันนะครับ

Source Code ของโปรเจคดูได้ที่ลิงก์ด้านล่างนี้ครับ

GitHub - tinnapat/spring-petclinic-opentelemetry: A sample Spring-based application with…

แก้โปรแกรมให้เพิ่มการเขียน Log

ก่อนอื่นผมขอแก้โปรแกรมของเรานิดนึง เพื่อให้มันเขียน Log ออกมาครับ ซึ่งเดี๋ยวเราจะเอาข้อมูล Log ตรงนี้ไปเชื่อมกับ Trace

ผมขอแก้หน้านี้นะครับ เป็นหน้าที่เข้าจากหน้าแรก กดเมนู Find Owner ด้านบน

จากนั้นกดปุ่ม “Find Owner” โดยไม่ต้องใส่ข้อมูลอะไร

คลิกที่ผลลัพธ์รายการไหนก็ได้ ก็จะพบกับหน้าแสดงข้อมูล Owner ที่มี ID ตามที่เราระบุใน URL จากตัวอย่างรูปข้างล่างนี้คือค้นหาด้วย Owner ที่มี ID = 1

ผมได้ทำการแก้โค้ดเป็นแบบนี้ครับ ด้วยการเพิ่มเขียน Log เข้าไปและให้เขียนค่าของ OwnerId ที่ส่งเข้ามาลงใน Log ด้วย

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
...

class OwnerController {

  private static Logger logger = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
  ...

  @GetMapping("/owners/{ownerId}")
  public ModelAndView showOwner(@PathVariable("ownerId") int ownerId) {
    logger.info("Enter showOwner with ownerId={}", ownerId);
    ...
  }
}

หลังจากแก้ไขโปรแกรมแล้ว เมื่อเราเปิดหน้าแสดงข้อมูล Owner จะเห็น Log ในหน้าจอ Console ในรูปแบบนี้

2023-10-17T16:24:06.004+07:00  INFO 15960 --- [nio-8080-exec-7] o.s.s.petclinic.owner.OwnerController    : Enter showOwner with ownerId=1

1. การนำ Trace ID และ Span ID ไปใส่ใน Log

เริ่มจากการนำ Trace ID และ Span ID จาก Trace ไปใส่ใน Log กันก่อน หลักการก็ง่าย ๆ ครับ คือ OpenTelemetry มี API ให้เราสามารถ Get ค่า Trace ID และ Span ID ออกมาได้ เราสามารถนำไปเขียนลง Log ได้เลย

Trace ID

Span.current().getSpanContext().getTraceId()

Span ID

Span.current().getSpanContext().getSpanId()

แต่ง่ายยิ่งกว่านั้น ถ้าหากว่าโปรแกรมของเราเขียน Log โดยใช้ Logging Framework ที่ OpenTelemetry รองรับอยู่แล้ว ตัว OpenTelemetry จะนำค่า Trace ID และ Span ID ไปใส่เป็นตัวแปร (หรือใน Logging Framework มักจะเรียกว่า MDC) ให้เราเลยโดยอัตโนมัติ ในชื่อ “trace_id” และ “span_id” ตามลำดับ โดยเราไม่ต้องเขียนโค้ดใด ๆ

Logging Framework ที่ OpenTelemetry รองรับคือ Log4j 1, Log4j 2 และ Logback

เรามาลองทำจริงกันดีกว่า วิธีการก็ง่ายมาก เนื่องจากโปรแกรมของเราเป็น Spring Boot ซึ่งใช้ Logging Framework เป็น SLF4J ซึ่งตัว OpenTelemetry รองรับอยู่แล้ว ดังนั้นผมจะแก้แบบนี้ครับ ด้วยการเพิ่ม Configuration ตัวนี้เข้าไปใน application.properties

logging.pattern.level=%5p [%X{trace_id:-},%X{span_id:-}]

Configuration ตัวนี้เป็นการกำหนด Format ของ Log Level ก็คือข้อความใน Log ตรงที่เป็นพวกคำว่า DEBUG, INFO, ERROR นั่นแหละครับ โดยเราบอกว่าให้เอาค่าตัวแปรที่ชื่อ trace_id และ span_id ที่อยู่ใน MDC (%X) ไปต่อท้ายค่าของ Log Level เดิม (%5p)

เมื่อแก้ไข Configuration แล้ว ลองเปิดเว็บเข้าหน้า Owner อีกครั้ง ก็จะพบแบบนี้ใน Log ครับ

2023-10-17T16:47:32.153+07:00  INFO [e52e195e499d7420c7c6f9433e604839,b4d6668fd9522cde] 16716 --- [nio-8080-exec-4] o.s.s.petclinic.owner.OwnerController    : Enter showOwner with ownerId=1

จะเห็นว่า ค่าที่อยู่หลังคำว่า INFO ในวงเล็บ ก็คือค่าของ Trade ID (e52e195e499d7420c7c6f9433e604839) และ Span ID (b4d6668fd9522cde) นั่นเอง

เมื่อผมลองเปิดดู Trace นี้ด้วย Jaeger UI ก็จะเห็นข้อมูล Trace ID และ Span ID ที่ตรงกัน

Trace ID ใน Jaeger UI อยู่ตรงบรรทัดแรกหลังชื่อ Trace

Span ID ใน Jaeger UI อยู่มุมขวาล่างของแต่ละ Span

ถ้า Trace มีจำนวนเยอะ ๆ เราสามารถเอา Trace ID ไปค้นหาในช่อง Search บน Jaeger UI ได้เลย และเมื่อเข้ามาในหน้าข้อมูลของ Trace แล้ว สามารถค้นหาด้วย Span ID โดยใส่ Span ID ในช่องบรรทัดถัดลงมาทางด้านขวาของชื่อ Trace ครับ ตัว Span ที่เราระบุก็จะถูกไฮไลท์เป็นสีเหลืองขึ้นมา

2. การนำข้อมูลจาก Log มาใส่ใน Trace

เรามาลองดูวิธีที่สองที่เราสามารถใช้เชื่อมความสัมพันธ์ระหว่าง Log กับ Trace กันบ้าง นั่นคือการเอาข้อมูลจาก Log มาใส่เป็น Span Attribute ใน Trace ครับ ซึ่งจริง ๆ แล้วการใส่ข้อมูลใน Span Attribute เนี่ย เราเอามาจากไหนก็ได้ อาจจะไม่จำเป็นต้องเป็นข้อมูลที่เราเขียนลง Log เสมอไป โดยเราสามารถค้นหา Trace ด้วยค่าเหล่านี้ได้ แต่ถ้าเราเขียนลง Log ด้วย ก็จะช่วยในการเชื่อมความสัมพันธ์กันได้ครับ

เนื่องจากการเอาข้อมูลใส่ Span Attribute ต้องทำผ่านการเขียนโค้ด เราก็ต้องเริ่มจากการเพิ่ม Dependency ของ OpenTelemetry API เข้าไปใน Project ของเราก่อน ดังนี้

<!-- OpenTelemetry -->
<dependency>
  <groupId>io.opentelemetry</groupId>
  <artifactId>opentelemetry-api</artifactId>
  <version>1.31.0</version>
</dependency>

จากนั้นง่าย ๆ เหมือนเดิมครับ เวลามีการเปิดหน้า Owner ใน Span นั้น ผมต้องการให้ใส่ค่า Owner ID เข้าไปด้วย โดยผมขอตั้งชื่อ Key ว่า “kbtg.demo.owner_id” สิ่งที่ต้องทำก็แค่เพิ่มโค้ดเข้าไปบรรทัดเดียวที่ Class เดิม ต่อหลังโค้ดที่แก้ตอนต้นให้เขียน Log ตามนี้เลยครับ

@GetMapping("/owners/{ownerId}")
public ModelAndView showOwner(@PathVariable("ownerId") int ownerId) {
logger.info("Enter showOwner with ownerId={}", ownerId);

Span.current().setAttribute("kbtg.demo.owner_id", ownerId);
...

หลังจากแก้โค้ดแล้ว ถ้าเรามาลองรันโปรแกรมดูอีกรอบ เปิดดูตรงส่วนของ Span เดิม ก็จะเห็นว่า ในส่วนของ Tag จะมี ค่า Span Attribute ที่เราเพิ่งเพิ่มเข้าไป โดยใช้ Key ที่ชื่อ “kbtg.demo.owner_id” ตามรูปครับ (Jaeger เรียก Span Attribute ว่า Tag)

นอกจากนี้ข้อดีของการเพิ่มข้อมูลลงไปใน Span Attribute คือเราสามารถค้นหา Trace จาก Span Attribute ได้ด้วย จากช่อง Tags ตามรูปนี้เลย

การค้นหาโดยใช้ Span Attribute

หวังว่าเนื้อหาในครั้งนี้ จะช่วยให้เพื่อน ๆ เล็งเห็นว่าอีกเรื่องที่มีความสำคัญ​ นอกเหนือจากการที่เรามี Trace และ Log แล้ว ข้อมูลที่อยู่ใน Trace และ Log ก็ควรจะเชื่อมโยงหากันไปมาได้ด้วย เพื่อที่เราจะได้ค้นหาข้อมูลที่ต้องการใช้งานได้อย่างรวดเร็ว ไม่เสียเวลาไปกับขั้นตอนที่ไม่เกิดประโยชน์ครับ

สำหรับบทความในตอนนี้ก็ขอจบแค่นี้ แล้วพบกันใหม่ตอนหน้าครับ

อ่านเพิ่มเติม

opentelemetry-java-instrumentation/docs/logger-mdc-instrumentation.md at main ·…

อ่านบทความอื่นๆ ในซีรีย์ Observability

Observability Pt. 1: ทำความรู้จักกับ Observability กันเถอะ

Observability Pt. 2: Tracing with OpenTelemetry and Jaeger

Observability Pt. 3: Manual Tracing Instrumentation with OpenTelemetry

สำหรับใครที่ชื่นชอบบทความนี้ อย่าลืมกดติดตาม Medium: KBTG Life เรามีสาระความรู้และเรื่องราวดีๆ จากชาว KBTG พร้อมเสิร์ฟให้ที่นี่ที่แรก