Segfault at atcprintf when player is kicked for exceeding processing time

[bottiger1]

Just found this logged crash dated 5 days old. It seems like this sourcemod function segfaulted when a player was kicked for exceeding processing time set by net_chan_limit_msec.

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0xe26a2021 in atcprintf (buffer=0xffe08a08 "check failed: curl ", maxlen=1024, format=0xd62aa2b0 "check failed: curl %i http %i", pCtx=0xd600f8d0, params=0xb710807c, param=0xffe089c8) at /sdk/sourcemod/core/logic/sprintf.cpp:1139
[Current thread is 1 (Thread 0xf7c6a700 (LWP 3134383))]
#0  0xe26a2021 in atcprintf (buffer=0xffe08a08 "check failed: curl ", maxlen=1024, format=0xd62aa2b0 "check failed: curl %i http %i", pCtx=0xd600f8d0, params=0xb710807c, param=0xffe089c8) at /sdk/sourcemod/core/logic/sprintf.cpp:1139
#1  0xe280ebb1 in SourceModBase::FormatString (this=0xe28b91b8 <g_SourceMod>, buffer=0xffe08a08 "check failed: curl ", maxlength=1024, pContext=0xd600f8d0, params=0xb710807c, param=2) at /sdk/sourcemod/core/sourcemod.cpp:676
#2  0xe2664559 in sm_LogError (pContext=0xd600f8d0, params=0xb710807c) at /sdk/sourcemod/core/logic/smn_filesystem.cpp:875
#3  0xb9a4e448 in ?? ()
#4  0xf55d7125 in CNetChan::Shutdown(char const*) [clone .part.121] () from /tf/bin/engine_srv.so
#5  0xf5540cb4 in CBaseClient::Disconnect(char const*, ...) () from /tf/bin/engine_srv.so
#6  0xf560e7cb in CGameClient::Disconnect(char const*, ...) () from /tf/bin/engine_srv.so
#7  0xf55d8167 in CNetChan::ProcessMessages(bf_read&) () from /tf/bin/engine_srv.so
#8  0xf55d9440 in CNetChan::ProcessPacket(netpacket_s*, bool) () from /tf/bin/engine_srv.so
#9  0xf55e134b in NET_ProcessSocket(int, IConnectionlessPacketHandler*) () from /tf/bin/engine_srv.so
#10 0xf5552e76 in CBaseServer::RunFrame() () from /tf/bin/engine_srv.so
#11 0xf561ed87 in SV_Frame(bool) () from /tf/bin/engine_srv.so

Client "! KxTher" connected (104.28.156.115:51924).
Entity 611 (class 'tf_weapon_flamethrower') reported ENTITY_CHANGE_NONE but 'm_hFlameManager' changed.
Msg from 104.28.156.115:51924: net_Tick after processing time exceeded (8 bytes), aborting connection after 198433 usec tick
Dropped ! KxTher from server (Processing time exceeded)

It appears to have been caused by the LogError function in this sourcemod plugin

public OnRequestComplete(CurlHandle request, curlcode, httpcode, size, int userid)
{
    if(curlcode != 0 || httpcode != 200) {
        LogError("check failed: curl %i http %i", curlcode, httpcode);
        Async_Close(request);
        return;
    }

SourceMod Version Information: SourceMod Version: 1.11.0.6922 SourcePawn Engine: 1.11.0.6922, jit-x86 (build 1.11.0.6922) SourcePawn API: v1 = 5, v2 = 16 Compiled on: Dec 1 2022 21:09:07 Built from: https://github.com/alliedmodders/sourcemod/commit/f9765981 Build ID: 6922:f9765981 http://www.sourcemod.net/

[Deathreus]

Nice IP

[ClaudiuHKS]

net_chan_limit_msec is 0 by default, did you change it?

@Deathreus :)

[bottiger1]

yes I changed it

[peace-maker]

Sourcepawn isn't multithreaded. Maybe that curl extension called into the vm from another thread? Got a link to the extension? Do you have an accelerator link?

[bottiger1]

The crash dump saying it is "Thread 1" means it is running on the main thread, not that there are multiple sourcemod threads running.

The extension I wrote only executes callback functions in OnGameFrame. It has never caused any issues like this in the past 9 years it has been used on our servers.

https://github.com/bottiger1/sourcemod-async/blob/8e4742f8067e01ee42f1284569dc6631f9fcef37/context.cpp#L52 https://github.com/bottiger1/sourcemod-async/blob/8e4742f8067e01ee42f1284569dc6631f9fcef37/extension.cpp#L54 https://github.com/bottiger1/sourcemod-async/blob/8e4742f8067e01ee42f1284569dc6631f9fcef37/extension.cpp#L317

I don't use accelerator since this is basically the same thing without needing to upload sensitive data to a 3rd party server.

[peace-maker]

It's hard to debug using only a stack trace though. Do you have a coredump handy to aid find the cause?

[bottiger1]

Never mind that was probably a corrupted stack trace. Just got another one of these crashes in a different place.

0 0xf58d51b2 in CNetChan::Shutdown(char const*) [clone .part.121] () from /tf/bin/engine_srv.so

1 0xf583ecb4 in CBaseClient::Disconnect(char const*, ...) () from /tf/bin/engine_srv.so

2 0xf590c85b in CGameClient::Disconnect(char const*, ...) () from /tf/bin/engine_srv.so

3 0xf58d61f7 in CNetChan::ProcessMessages(bf_read&) () from /tf/bin/engine_srv.so

4 0xf58d6ef3 in CNetChan::CheckReceivingList(int) () from /tf/bin/engine_srv.so

5 0xf58d749f in CNetChan::ProcessPacket(netpacket_s*, bool) () from /tf/bin/engine_srv.so

6 0xf58df3db in NET_ProcessSocket(int, IConnectionlessPacketHandler*) () from /tf/bin/engine_srv.so

7 0xf5850e76 in CBaseServer::RunFrame() () from /tf/bin/engine_srv.so

8 0xf591ce17 in SV_Frame(bool) () from /tf/bin/engine_srv.so

Msg from :27005: net_SetConVar after processing time exceeded (19 bytes), aborting connection after 7179362 usec tick

I'm guessing the only way it could work is by doing unsafe thread interrupts, there's just no way to safely use net_chan_limit_msec.