Hardware, OS or Go Compiler problems on game server

[tongohiti]

Есть довольно веские основания считать, что на игровом сервере имеются проблемы либо с железом (сбойная память, например), либо с операционной системой, либо с компилятором Go.

С самого начала тестового периода наблюдается необъяснимое поведение решения на Go, которое падает в рандомный момент с совершенно нелепыми ошибками (стектрейсы которых удалось увидеть благодаря недавним улучшениям логгирования упавших стратегий). При этом вне игрового сервера данное решение ведёт себя на 100% стабильно (в Local Runner под Windows).

Свежий пример: игра №88806 (http://aicups.ru/session/88806/). После падения стратегии на 75 тике в консоли браузера имеем:

Tick[0] Ready!
{"FOOD_MASS":2.163798834331256,"GAME_HEIGHT":990,"GAME_TICKS":7500,"GAME_WIDTH":990,"INERTION_FACTOR":9.9187231689895015,"MAX_FRAGS_CNT":14,"SPEED_FACTOR":34.19110572762699,"TICKS_TIL_FUSION":228,"VIRUS_RADIUS":34.21743004020847,"VIRUS_SPLIT_MASS":67.918386077693214,"VISCOSITY":0.44268002505130472}
{"Mine":[{"Id":"4","M":40,"R":12.649110640673518,"SX":0,"SY":0,"TTF":2097277,"X":110.3,"Y":689.70000000000005}],"Objects":[{"T":"F","X":99,"Y":688},{"Id":"21","M":40,"T":"V","X":235.43486008041694,"Y":210.43486008041694},{"Id":"22","M":40,"T":"V","X":754.56513991958309,"Y":210.43486008041694},{"Id":"23","M":40,"T":"V","X":754.56513991958309,"Y":779.56513991958309},{"Id":"24","M":40,"T":"V","X":235.43486008041694,"Y":779.56513991958309}]}

Tick[1] {"Mine":[{"Id":"4","M":42.163798834331253,"R":12.986731510943198,"SX":0,"SY":0,"TTF":2097276,"X":110.3,"Y":689.70000000000005}],"Objects":[{"Id":"21","M":40,"T":"V","X":235.43486008041694,"Y":210.43486008041694},{"Id":"22","M":40,"T":"V","X":754.56513991958309,"Y":210.43486008041694},{"Id":"23","M":40,"T":"V","X":754.56513991958309,"Y":779.56513991958309},{"Id":"24","M":40,"T":"V","X":235.43486008041694,"Y":779.56513991958309}]}
>>Result: (110.3, 194.7)

. . . . .

Tick[74] {"Mine":[{"Id":"4","M":42.163798834331253,"R":12.986731510943198,"SX":3.2242160409488292e-16,"SY":-5.2655443891147291,"TTF":2097203,"X":110.3,"Y":322.43317511395833}],"Objects":[{"Id":"21","M":40,"T":"V","X":235.43486008041694,"Y":210.43486008041694},{"Id":"22","M":40,"T":"V","X":754.56513991958309,"Y":210.43486008041694},{"Id":"23","M":40,"T":"V","X":754.56513991958309,"Y":779.56513991958309},{"Id":"24","M":40,"T":"V","X":235.43486008041694,"Y":779.56513991958309}]}
>>Result: (110.3, 194.7)

после чего стратегия упала:

Tick[75] unexpected fault address 0x0
fatal error: fault

Tick[76] Решение отключилось от механики до окончания!

По этим логам вполне можно воссоздать все входные данные, которые получала стратегия. Собираем, сохраняем в файл, дополнительно скопировав последнюю строчку несколько раз (чтобы были дополнительные тики после оригинального падения). Запускаем ту же самую стратегию под Windows, скормив полученный файлик на вход. Стратегия работает, генерируя на 100% совпадающий output! WTF?!

Стратегия детерминированная, random не использует, поэтому результаты работы воспроизводимые. За неделю тестов было перепробовано множество вариантов кода, включая самые тривиальные (читаем вход, пара if/else, пишем выход). Стратегия строго последовательная, горутины и каналы не используются вообще. В разных играх стратегия падает с разными ошибками, включая паники, SIGSEGV, null pointer dereference и просто непонятные unexpected fault address 0x0. Чтобы добавить перцу, в некоторых случаях по стектрейсу видна ошибка записи в stdout, что вообще в нормальных условиях происходить не должно. Налицо проблема порчи данных в памяти.

Сам по себе язык Go достаточно безопасный, и вызвать подобное поведение в нём (не прибегая к unsafe-коду с указателями) довольно проблематично. Проблемы с многопоточностью сразу исключаем, т.к. код, как я уже написал выше, однопоточный.

Из всего вышенаписанного напрашивается вывод, что на игровом сервере что-то не в порядке.

Прошу помощи у администрации!

[tongohiti]

Ещё пример падения:

Tick[18] [signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x414f85]

goroutine 1 [running]:

runtime.throw(0x7fdf3f166088, 0x5)
    /usr/lib/go-1.10/src/runtime/panic.go:619 +0x83 fp=0xc420363ba0 sp=0xc420363b80 pc=0x7fdf3eb51363

runtime.sigpanic()
    /usr/lib/go-1.10/src/runtime/signal_unix.go:395 +0x215 fp=0xc420363bf0 sp=0xc420363ba0 pc=0x7fdf3eb6b2d5

io.WriteCommand(0xc061525f14d99bc6, 0x40871cc285d65b63, 0x0, 0xc420300000, 0x30a, 0x0)
    /opt/client/solution/io/io.go:57 +0xa5 fp=0xc420363d00 sp=0xc420363bf0 pc=0x414f85

runner.Run()
    /opt/client/solution/runner/runner.go:39 +0x53d fp=0xc420363f50 sp=0xc420363d00 pc=0x41f7bd

main.main()
    /opt/client/solution/main.go:12 +0x91 fp=0xc420363f88 sp=0xc420363f50 pc=0x421331

runtime.main()
    /usr/lib/go-1.10/src/runtime/proc.go:198 +0x24f fp=0xc420363fe0 sp=0xc420363f88 pc=0x7fdf3eb53b0f

runtime.goexit()
    /usr/lib/go-1.10/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420363fe8 sp=0xc420363fe0 pc=0x7fdf3eb89

Tick[20] Решение отключилось от механики до окончания!

[tongohiti]

Ещё пример, наглядно показывающий всю дичь происходящего:

Tick[2767] 2018/04/03 09:24:07 Error writing answer to stdout Circle(715.6, 683.3), 79.0
2018/04/03 09:24:07 Written bytes: 0
2018/04/03 09:24:07 {"X":637,"Y":876,"Split":false,"Eject":false,"Debug":"","Sprite":null}

Tick[2768] Решение отключилось от механики до окончания!

Здесь стратегия пишет свой ответ в stdout, в ответ получает ошибку (код на Go: n, err := writer.WriteString(result), где n - это количество по факту записанных байт, и err - объект ошибки). По логу видно, что запись в stdout прошла неудачно, записано 0 байт (что само по себе в спокойной жизни нонсенс), а вместо кода ошибки вернулся Circle(715.6, 683.3), 79.0 - это вообще не код ошибки, а некий посторонний объект с хипа (класс из моей стратегии, да). Т.е. налицо серьёзное повреждение данных в памяти. При этом, повторюсь, сам язык Go достаточно безопаснен, там довольно непросто так выстрелить себе в ногу.

[tongohiti]

Попробовал собрать эти же исходники под Linux. Запустил в виртуалке (Linux Mint 64bit) - работает так же стабильно. Собранный для Linux бинарник также работает и не падает у других людей. А на сервере падает. Версия кода вот эта: http://aicups.ru/solution/6923/

[BorisKolganov]

Понизил версию GO до 1.6 на тестовых серверах помогло

[tongohiti]

Пока не падает! Точнее, было два падения с тайм-аутом, но тут я на 99% уверен что сам виноват, т.к. для тестов закоммитил очень сырой код, зато с потоками, каналами и вот это вот всё.

[tongohiti]

Думаю, тикет можно закрывать. Ещё раз спасибо @BorisKolganov!

[alex3d]

@tongohiti если есть желание поэкспериментировать можешь попробовать под линуксом собрать свою стратегию go 1.10 и посмотреть будут ли проблемы с:

ulimit -u 5
./mybot < input.json

Игры пускаются с лимитом на 20 потоков, но возможно часть этих потоков расходует tcp-proxy. Возможно в какой-то момент go превышает этот лимит (например, при запуске GC)

[tongohiti]

@alex3d

@tongohiti если есть желание поэкспериментировать

Да пока с этим проблем не было, хотя горутины создаю активно, так что повременю, зачем лечить здорового. Потом попробую, если будут проблемы.

[243083df]

Очень похоже на баг описанный тут: https://habrahabr.ru/company/mailru/blog/344080/

[alex3d]

хех, а ведь golang уже наступал на эти грабли несколько лет назад: https://twitter.com/bcantrill/status/774290166164754433