Spring - Log Http Request , Response

Programming

Spring - Log Http Request , Response

ปัญหาหนึ่งที่มักเจอเสมอเวลาติดต่อกับ Thrid party คืออีกฝั่งตอบ Error กลับมา ซึ่ง Error ที่ตอบกลับมานั้นถ้าโชคดีหน่อยเขาจะบอกรายละเอียดแน่ชัดมาเลยว่าเป็นที่อะไร แต่ในกรณีที่โชคไม่ดีหน่อยเพราะ API ที่เขาทำนั้นเขาทำแบบเร่ง หรือ เขามั่นใจว่าคุณจะทำการส่งข้อมูลที่ถูกต้องให้เขาเสมอ เมื่อเกิดการ Error ขึ้นเขาก็แค่บอกว่า Error กลับไป ไม่ได้บอกเป็นที่อะไร ซึ่งด้วยผลลัพธ์แบบนี้บอกเลยว่า “หัวร้อน” แน่นอนครับ และเมื่อเขาเป็น Thrid party คุณไม่ใช่เจ้านายเขา คุณไม่มีอำนาจใดๆมากพอไปสั่งเขาได้ (ผมเคยเห็นคนมีอำนาจมากพอสั่งหน่วยงานอื่นได้นะ ผมนี่อย่างว้าวกับคนนั้นมากเลย) ดังนั้นวิธีการที่คุณพอจะทำได้คือ เอา Request , Response ที่ในรอบนี้เกิดปัญหานั้น ส่งให้ Third party เพื่อให้เขาบอกว่ามันเกิดปัญหาจากอะไร

Source code

source code ทั้งหมดที่ใช้เป็นตัวอย่างสามารถดูได้ที่ https://github.com/surapong-taotiamton/spring-log-request-response

Spring Http request

สมมุติผมทำ API ที่รับ Request param แล้วยิงต่อไปดึงข้อมูลต่อที่ https://jsonplaceholder.typicode.com/ เพื่อจำลองการติดต่อกับ Thrid party โดยถ้าเราเขียน Code โดยใช้ Spring เราสามารถเขียน Code เพื่อดึงข้อมูลได้ประมาณนี้ 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
@RestController
public class TestThirdPartyController {

    private static final Logger logger = LoggerFactory.getLogger(TestThirdPartyController.class);

    @GetMapping("/todo/{id}")
    public ToDoDto getToDo(
            @PathVariable("id") String id
    ) {
        String url = "https://jsonplaceholder.typicode.com/todos/" + id;
        RestTemplate restTemplate = new RestTemplate();
        ResponseEntity<ToDoDto> responseEntity = restTemplate.exchange(url, HttpMethod.GET, HttpEntity.EMPTY, ToDoDto.class);
        return responseEntity.getBody();
    }

}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
// ToDoDtoClass

package blog.surapong.example.logrequestresponse.api.dto;

import lombok.EqualsAndHashCode;
import lombok.Getter;
import lombok.Setter;
import lombok.ToString;
import lombok.experimental.Accessors;

@Getter
@Setter
@Accessors(chain = true)
@EqualsAndHashCode
@ToString
public class ToDoDto {
    private Long userId;
    private Long id;
    private String title;
    private Boolean completed;
}

โดย Code ไม่มีอะไรทำมากไปกว่าคือรับ Id จาก Path variable จากนั้นยิงต่อไปที่ https://jsonplaceholder.typicode.com/todos/ เพื่อเอา Response กลับมา ซึ่งเมื่อทดลองผ่านหน้าจอจะได้ดังภาพ

โอเคคราวนี้ถ้าเราใส่ id เป็น 3000 เราจะได้ Error ดังภาพ

คราวนี้ก็จะเกิด Error ขึ้นครับ คราวนี้ถ้าเราอยากจะทราบว่าเราส่ง Request Response อะไรไปให้ Third party บ้างเราก็ต้องเขียน Code เพิ่มขึ้นมาครับ ซึ่งมีคนแนะนำไว้แล้วซึ่งตามไปอ่านได้ที่ : https://www.baeldung.com/spring-resttemplate-logging เขาอธิบายวิธีการไว้หมดแล้ว

อ้าวแล้วจะเขียนทำไมวะ จริงๆคือด้วยความขี้เกียจของผมคือ ไม่อยากเขียนเองเลยไปหาต่อว่ามีใครเขียนอะไรแบบนี้ไว้แล้วบ้าง ซึ่งก็เจอครับ ซึ่งนั่นก็คือ zalando-logbook

ใช้ Zalando-Logbook ทำ Log Request Response

เพิ่ม Dependency ลงใน Pom

เพิ่ม Dependency ลงใน pom นะครับ

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
<!-- Log http request response -->

<dependencies>

    <!-- Another lib -->

    <dependency>
        <groupId>org.zalando</groupId>
        <artifactId>logbook-spring-boot-starter</artifactId>
        <version>2.6.2</version>
    </dependency>

    <dependency>
        <groupId>org.zalando</groupId>
        <artifactId>logbook-core</artifactId>
        <version>2.6.2</version>
    </dependency>

    <dependency>
        <groupId>org.zalando</groupId>
        <artifactId>logbook-httpclient</artifactId>
        <version>2.6.2</version>
    </dependency>

</dependencies>

เพิ่ม Config ใน application.properties

เพิ่มค่า config เข้าไปใน application.properties ดังค่าด้านล่าง

1
logging.level.org.zalando.logbook=TRACE

ทำการแก้ไขตรงส่วน Call Http requeset ไปที่ Third party

ในการเรียก Http request ไปหา Thrid party นั้นเราจะใช้ RestTemplate ของ Spring ซึ่งมันสามารถสร้าง Interceptor เข้าไปใน RestTemplate เพื่อ Log Request Response ได้ โดยถ้าอ่านตัวอย่างจาก baeldung เขาจะให้เรา Implement เอง แต่ของผมนั้นจะไปใช้ Lib ของ zalando ซึ่งทำให้การสร้าง RestTemplate ของผมจึงแยกมาเป็น Private method ดังด้านล่าง เพราะทุกครั้งที่ทำการ Config RestTemplate แบบนี้ทุกครั้ง เลยแยกออกมาเลยเพื่อจะได้ใช้ได้หลายที่

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
private RestTemplate createRestTemplate() {

    
    // ตรงนี้สร้างตัว Client request factory ให้ RestTemplate โดยสร้างเป็นแบบ Buffering เพื่อให้สามารถเข้าไปอ่าน
    // Request Response ได้หลายรอบ ไม่ติดปัญาเรื่อง Stream ที่อ่านได้รอบเดียว

    SimpleClientHttpRequestFactory simpleClientHttpRequestFactory = new SimpleClientHttpRequestFactory();
    simpleClientHttpRequestFactory.setOutputStreaming(false);

    ClientHttpRequestFactory factory =
            new BufferingClientHttpRequestFactory(simpleClientHttpRequestFactory);

    RestTemplate restTemplate = new RestTemplate(factory);

    // ตรงนี้เป็นการสร้าง Interceptor เพื่ออ่านค่า Request Response ซึ่งเราใช้ตัวของ
    // Zalando log book

    Logbook logbook = Logbook.create();
    LogbookClientHttpRequestInterceptor interceptor = new LogbookClientHttpRequestInterceptor(logbook);

    restTemplate.getInterceptors().add(interceptor);
    return  restTemplate;
}

อันนี้ส่วนที่เรียกใช้งาน โดยขอเพิ่มอีก Endpoint นึงเลยเพื่อง่ายในการดูความแตกต่าง

1
2
3
4
5
6
7
8
9
@GetMapping("/todo/log/{id}")
public ToDoDto getToDoLog(
        @PathVariable("id") String id
) {
    String url = "https://jsonplaceholder.typicode.com/todos/" + id;
    RestTemplate restTemplate = createRestTemplate();
    ResponseEntity<ToDoDto> responseEntity = restTemplate.exchange(url, HttpMethod.GET, HttpEntity.EMPTY, ToDoDto.class);
    return responseEntity.getBody();
}

มาดูผลลัพธ์กัน

เราลองเรียกใช้งาน API ผ่าน http://127.0.0.1:8080/todo/log/1 จะได้ผลลัพธ์ดังภาพ

คราวนี้ลองไปดูใน Console log ของ Server จะได้

ในภาพอาจจะเห็นไม่เต็มมาลองดู Log เต็มๆ จะได้ดังภาพ

1
2
3
4
5
6
7
8
9
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
# ส่วนที่ยิงออกไปหา Thrid party
2564-05-16 14:05:18.680 TRACE 14560 --- [nio-8080-exec-1] org.zalando.logbook.Logbook              : Outgoing Request: adf2666b770005ba
Remote: localhost
GET https://jsonplaceholder.typicode.com/todos/1 HTTP/1.1
Accept: application/json, application/*+json
Content-Length: 0

# ส่วนที่ได้ตอบกลับจาก Thrid party
2564-05-16 14:05:19.051 TRACE 14560 --- [nio-8080-exec-1] org.zalando.logbook.Logbook              : Incoming Response: adf2666b770005ba
Duration: 366 ms
HTTP/1.1 200 OK
Accept-Ranges: bytes
Access-Control-Allow-Credentials: true
Age: 24883
alt-svc: h3-27=":443"; ma=86400, h3-28=":443"; ma=86400, h3-29=":443"; ma=86400
Cache-Control: max-age=43200
CF-Cache-Status: HIT
CF-RAY: 6502c1ca8e36cbe4-SIN
cf-request-id: 0a159772930000cbe44012e000000001
Connection: keep-alive
Content-Length: 83
Content-Type: application/json; charset=utf-8
Date: Sun, 16 May 2021 07:05:19 GMT
Etag: W/"53-hfEnumeNh6YirfjyjaujcOPPT+s"
Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
Expires: -1
NEL: {"report_to":"cf-nel","max_age":604800}
Pragma: no-cache
Report-To: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=j1GrG6LPL61zeVNMq1b%2BvOiB%2FQgsoj9XZObn4GuEwHvo6tneWSaWQiD25XJildqvBj0eKheWN65tswB9%2Bw0UFhEDteZ4dqeSQJMZXDOyb4QfecfHQz1rihuTmQVd"}],"group":"cf-nel","max_age":604800}
Server: cloudflare
Vary: Origin, Accept-Encoding
Via: 1.1 vegur
X-Content-Type-Options: nosniff
X-Powered-By: Express
X-Ratelimit-Limit: 1000
X-Ratelimit-Remaining: 999
X-Ratelimit-Reset: 1620749436

{"userId":1,"id":1,"title":"delectus aut autem","completed":false}

ลองในกรณี Error กันบ้าง

คราวนี้มาลอง Test กรณี Error กันบ้าง โดยยิงไปที่ : http://127.0.0.1:8080/todo/log/3000

ซึ่งเมื่อไปดูใน Log แล้วจะได้ข้อความด้านล่าง ซึ่งเราจะเห็น Request Response โดยส่วน Response นั้นตอบกลับมาเป็น 404 

1
2
3
4
5
6
7
8
9
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

# ส่วนที่ยิงออกไปหา Thrid party
2564-05-16 14:15:26.734 TRACE 14560 --- [nio-8080-exec-4] org.zalando.logbook.Logbook              : Outgoing Request: ca08db405127d62b
Remote: localhost
GET https://jsonplaceholder.typicode.com/todos/3000 HTTP/1.1
Accept: application/json, application/*+json
Content-Length: 0

# ส่วนที่ได้ตอบกลับจาก Thrid party
2564-05-16 14:15:26.943 TRACE 14560 --- [nio-8080-exec-4] org.zalando.logbook.Logbook              : Incoming Response: ca08db405127d62b
Duration: 207 ms
HTTP/1.1 404 Not Found
Access-Control-Allow-Credentials: true
Age: 4122
alt-svc: h3-27=":443"; ma=86400, h3-28=":443"; ma=86400, h3-29=":443"; ma=86400
Cache-Control: max-age=43200
CF-Cache-Status: HIT
CF-RAY: 6502d0a1f9dc5653-SIN
cf-request-id: 0a15a0b93b00005653f01d9000000001
Connection: keep-alive
Content-Length: 2
Content-Type: application/json; charset=utf-8
Date: Sun, 16 May 2021 07:15:27 GMT
Etag: W/"2-vyGp6PvFo4RvsFtPoIWeCReyIC8"
Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
Expires: -1
NEL: {"report_to":"cf-nel","max_age":604800}
Pragma: no-cache
Report-To: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=Pe3fXWnj8LWKvbjsXIXnl4%2Fqz%2FXwCBt4qn7Nfhl9USShQUIRP0%2FCtDXkbKD0kV1uGdx56xFCCaCb0sDspaOm6uJi%2BYeM%2FmXbiBUkeY6E6Uh72Z7tLg8M%2FvF0CCBq"}],"group":"cf-nel","max_age":604800}
Server: cloudflare
Vary: Origin, Accept-Encoding
Via: 1.1 vegur
X-Content-Type-Options: nosniff
X-Powered-By: Express
X-Ratelimit-Limit: 1000
X-Ratelimit-Remaining: 999
X-Ratelimit-Reset: 1621145265

{}

สรุป

สำหรับตอนนี้เราก็ได้วิธีการ Log Http Request Response เวลายิงไป Third party ไปแล้วนะครับ โดยในตัวอย่างของผมยิงเป็น Method GET ฝั่งที่ยิงออกไปเลยไม่ค่อยตัว Body แต่หากคุณลองไปยิงด้วย Method อื่น เช่น PUT , POST คุณจะเห็นตัว Body ของ Http Request ด้วยครับ โดยในส่วนของ Logbook นั้นสามารถกำหนด Format ของ Log ที่ออกมาได้ และสามารถเลือกได้ว่าจะเอาสส่วนไหนของทั้ง Request และ Response มาแสดงได้ โดยสามารถอ่าน Config ได้ที่ https://github.com/zalando/logbook ครับ

เพลงประกอบการเขียน Code

เพลงเก่าแต่ความหมายเพลงไม่เคยเก่า พี่มอสพี่แคทนี่เขาเป็นอมตะกันเหรอครับ หน้าตายังกะสตาฟไว้