יום חמישי, 23 באוקטובר 2014

234 Fogcast 14 - My bug!

הפעם שוחחו ליאור ורן על אחת מהחוויות שכל מפתח עובר בחייו - באגים. אבל לא סתם באגים - באגים קשים, מתסכלים, כאלה שעובדים עליהם ימים, שבועות או יותר...

במקרה ספציפי זה רן נתקל בבאג שעליו הוא כבר עובד מספר שבועות (בהפסקות, אבל זמן ממושך) וביחד רן וליאוד ניסו לנתח דרכי פעולה אפשריות ולהעלות השערות לגבי היתכנות פתרונו. 

הבאג הוא ככל הנראה ״לא בקוד שלנו״ או לפחות כך אנו מקווים, מפאת הפאדיחה, וככל הנראה הוא בקוד של צד שלישי, אבל לא ברור איזה כי יש איזה שלושה צדדים שלישיים שמעורבים בעניין. בקיצור, באג מאתגר...
להלן כמה לינקים, בין השאר לדיווח על הבאג ומידע כללי לצורך ההקשר.
Picks:
הקובץ נמצא כאן, האזנה נעימה

10 תגובות:

דן לויסון אמר/ה...

Hi Ran,
It sounds to me like the bug is in the set-cookie header, when you try to write too big cookie you might get this exception.
Since many times cookies are incremental (you add data to existing data) the cause can
be specific users that have big cookies.
If you have server stickiness that can explain why it happens on one server only.
good luck
-Dan

Ran Tavory אמר/ה...

Hi Dan thanks for the idea. Cookies are a good direction to check although I should note that I'm not setting any cookies at all. But perhaps something configures the server to echo the values of the cookies received and maybe sometimes even modify them. I'll check.
BTW I checked further on and it seems to be not related to one specific request, it's more about load or perhaps many concurrent requests (not necessarily under load) that any one specific request.

Moshe Eshel אמר/ה...

שלום רן,

הזכרת בפודקסט כלי (השם בהקלטה לא ברור) שנכתב בGo שמקליט/משכפל תנועת HTTP על ידי האזנה, אתה יכול לצרף URL אולי?
אני צריך אותו כדי לדבג בעיות שיש לי ב (הפתעה, הפתעה) Dropwizard... כל מיני שגיאות בלוג ועניינים אחרים שאני לא רואה את הבקשות עצמן בלוג (שגיאה שאמורה להחזיר 413 ואין כאלה בלוג), הפיצול המוחלט בין הלוגים (בקשות/AccessLog ואפליקציה) והעובדה שאין ממש דרך לקשר בין שגיאה פה לבקשה שם מטריפה אותי. יותר מזה, יש בהחלט מצב שחלק מהבקשות (באג אחר) בכלל לא נכתבות ללוג כי העיבוד שלהן לא מסתיים.

תודה

Ran Tavory אמר/ה...

There you go Moshe
https://github.com/buger/gor

Moshe Eshel אמר/ה...

תודה רבה! אין לך מושג כמה זמן אני מחפש בדיוק את הדבר הזה...

Ran Tavory אמר/ה...

Thanks everyone for your help, I found the issue (my bug, surprise surprise) and fixed it.

משה סייג אמר/ה...

שלום רן,

סיפרת על כך שלפעמים המערכת מגיעה לרצף של שגיאות NullPointerException אבל לא מודפס stack trace.
הסיבה לכך נעוצה באופטימיזציה שנעשית ע"י ה-JVM כששגיאה נזרקת הרבה פעמים. השגיאה מודפסת במלואה בפעמים הראשונות ואז ה-JVM מחליט לחסוך את איסוף המידע ואת וההדפסה ומדפיס רק את העובדה שקרתה שגיאה.

דרך אחת להתגבר על כך היא למצוא את אותן השגיאות הראשונות שהודפסו במלואן לפני שהאופטימיזציה נכנסה ולחקור אותן.
אפשרות אחרת היא לומר ל-JVM לא לבצע את האופטימיזציה כלל ע"י הרצת ה-JVM עם הדגל
XX:-OmitStackTraceInFastThrow-

בהצלחה

Ran Tavory אמר/ה...

אה תודה משה, לא ידעתי את זה, מאוד שימושי!

avi אמר/ה...

Well...

Please tell us what was the bug :-)

Ran Tavory אמר/ה...

Hi Avi, the bug was incorrect reuse or a response object in legacy code which surprisingly worked well in the previous implementation but did not work well in the new implementation.
The fix is to create a new response object with each response, never reuse those

הוסף רשומת תגובה