ไม่ได้เขียนบล็อกเสียนาน เร็วๆนี้เจอเหตุการณ์ประหลาดเลยมาจดไว้เสียหน่อย

Incident

Incident ที่เจอคือ http response header หายไปที่ environment นึง ทั้งๆที่ใช้ code เดียวกันกับ env อื่น ที่มี header ตามปกติ

สมมติฐานแรกคือเป็นที่ Infra เลยได้มีการไล่เช็คแล้วเช็คอีก เสียเวลาไปร่วมๆ 4-5 ชม.

จนกระทั่งได้ลองเข้าไปเรียก api request จากภายใน pod เดียวกันกับ service และเจอว่า header ก็ยังหายอยู่

สมมติฐาน

หนึ่งในทีมงานเจอว่า code ในการ write header มาทีหลัง write body, ซึ่งใน documentation บอกไว้ว่าถ้ามีการ write body จะถือว่าจบ และส่ง response ทันทีโดยไม่สนใจ header ที่มา write ภายหลัง

แก้ code ไป ยังไม่ทันได้ deploy ยังมีคำถามอยู่ว่าแล้วทำไม env อื่นๆถึงมี header กลับมาได้ ทั้งๆที่ code เดียวกัน

จับผู้ร้าย

ทีมงานอีกคนบอกว่าไปเจอว่าสิ่งที่ต่างกันในแต่ละ env คือ log level โดย env ที่ header หาย มี log level ที่ละเอียดน้อยกว่า env ที่ทำงานได้

เมื่อลองปรับ log level ให้ละเอียดขึ้นก็เจอว่า header ที่หายไปโผล่มาแล้ว

และลองปรับ log level ของ env อื่นที่เคยทำได้ปกติให้ละเอียดน้อยลง ก็เจอพฤติกรรม header หายเหมือนกัน

สรุปปัญหา

เลยถึงบางอ้อว่า เมื่อใช้ log level ที่ละเอียดสูงกว่า, OS จะมีงานทำมากขึ้นจนไม่ได้ flush network buffer ทันทีที่สั่ง write body

พอมา set header ทีหลัง เนื่องจาก packet ยังไม่ได้ส่งออกไป ก็เลยสามารถแก้ได้

ถ้า OS งานน้อยลงจากการที่ไม่ต้องพ่น log เยอะๆ ก็สามารถ flush network ได้ทันที พอสั่งเติม header ทีหลังก็เจอว่า packet ถูกส่งออกไปแล้ว

Analogy

เปรียบเทียบเหมือนจ้างพี่วินส่งของโดยตกลงว่า ถ้าเห็นกล่องสีแดงวางบนรถให้ออกไปส่งได้เลย

ถ้าอยากให้พี่วินส่งพร้อมกันสองกล่อง ที่ถูกต้องก็ต้องเอากล่องสีแดงมาวางทีหลังอีกกล่องนึง เพราะถ้าวางกล่องแดงก่อน ตอนเดินกลับไปยกอีกกล่องนึง พี่วินก็อาจจะออกรถไปแล้ว

แต่ในกรณี log level ละเอียด

ก็คือพี่วินไม่ได้นั่งเฝ้าที่รถ แต่ออกไปทำอย่างอื่นอยู่ ถึงเราจะพลาดโดยเอากล่องแดงมาวางบนรถก่อน

แต่ระหว่างที่เราเดินไปยกกล่องที่สองมาวางที่รถ ถ้าพี่วินยังไม่กลับมาเราก็เอามาวางทัน แล้วพอพี่วินกลับมา ก็จะออกรถไปโดยมีทั้งสองกล่อง