runtime error when parsing demo file #162

marksamman · 2019-11-23T18:49:25Z

Describe the bug
This started happening in the past 24 hours, probably related to recent CS:GO update. New demo files are causing the parser to crash. Trace:

panic: runtime error: invalid memory address or nil pointer dereference [recovered]
        panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0xbc337d]

goroutine 88 [running]:
github.com/markus-wa/demoinfocs-golang.recoverFromUnexpectedEOF(...)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/parsing.go:119
github.com/markus-wa/demoinfocs-golang.(*Parser).handlePacketEntities.func1(0xc00052c000)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/entities.go:14 +0x131
panic(0xe65d80, 0x18f2110)
        /usr/local/Cellar/go/1.13.4/libexec/src/runtime/panic.go:679 +0x1b2
github.com/markus-wa/demoinfocs-golang.(*Parser).bindNewPlayer(0xc00052c000, 0x11e8e60, 0xc000066ae0)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/datatables.go:196 +0x10ad
github.com/markus-wa/demoinfocs-golang.(*Parser).bindPlayers.func1(0xc000066ae0)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/datatables.go:166 +0x40
github.com/markus-wa/demoinfocs-golang/sendtables.(*ServerClass).newEntity(0xc0009efcc0, 0xc00018a3f0, 0x7, 0x8000000000000000)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/sendtables/sendtables.go:120 +0x2f0
github.com/markus-wa/demoinfocs-golang/sendtables.(*SendTableParser).ReadEnterPVS(0xc00018a0e0, 0xc00018a3f0, 0x7, 0x19289a0)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/sendtables/st_parser.go:290 +0xc8
github.com/markus-wa/demoinfocs-golang.(*Parser).handlePacketEntities(0xc00052c000, 0xc00459ce40)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/entities.go:43 +0x296
reflect.Value.call(0xdfa3e0, 0xc000568040, 0x13, 0xfb1c17, 0x4, 0xc00026bf68, 0x1, 0x1, 0xc0000b2058, 0x80422c3f6e15e01, ...)
        /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:460 +0x5f6
reflect.Value.Call(0xdfa3e0, 0xc000568040, 0x13, 0xc00026bf68, 0x1, 0x1, 0x0, 0x0, 0x0)
        /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:321 +0xb4
github.com/markus-wa/godispatch.(*Dispatcher).Dispatch(0xc00052c020, 0xf7f380, 0xc00459ce40)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/godispatch@v1.1.0/dispatch.go:48 +0x24f
github.com/markus-wa/godispatch.(*Dispatcher).dispatchQueue(0xc00052c020, 0xc0000661e0)
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/godispatch@v1.1.0/dispatch.go:97 +0xf4
created by github.com/markus-wa/godispatch.(*Dispatcher).AddQueues
        /Users/mark/Projects/go/pkg/mod/github.com/markus-wa/godispatch@v1.1.0/dispatch.go:83 +0x183

To Reproduce
Download link to an affected demo: https://www.dropbox.com/s/wom10hgr218yn3r/mrec_19_11_22_37_39.dem?dl=0

Code:

p := dem.NewParser(bytes.NewReader(content))
p.RegisterEventHandler(func(e events.SayText2) {
	if len(e.Params) < 2 {
		return
	}

	duration := p.CurrentTime()
	totalSeconds := int64(math.Floor(duration.Seconds()))
	minutes := totalSeconds / 60
	seconds := totalSeconds % 60
	chatLogBuf.WriteString(
		fmt.Sprintf(
			"[%dm:%ds] %s<%s>: %s\n",
			minutes,
			seconds,
			e.Params[0],
			e.MsgName,
			e.Params[1],
		),
	)
})
if err = p.ParseToEnd(); err != nil {
	errors = append(errors, err)
}

Expected behavior
Parser shouldn't crash.

Library version
v1.5.1

The text was updated successfully, but these errors were encountered:

markus-wa · 2019-11-23T22:16:58Z

Thanks for bringing this to my attention @marksamman.

I'm not sure if this is really related to any update. I think it's just a fairly strange demo in general.

Anyway, I've filed #163 which should fix this issue. Please verify if it helps and I will merge it asap.

we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

marksamman · 2019-11-24T11:30:02Z

It has happened more than once in demo files from the past two days, so I'm not sure what else it would be if not for an update. I've processed about 20TB of demo files in the past without this happening. Either way, your fix addresses the problem. Thanks!

marksamman · 2019-11-24T11:33:30Z

Experiencing a different crash now:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x1fe pc=0xbc848c]

goroutine 82 [running]:
github.com/markus-wa/demoinfocs-golang.gameEventHandler.weaponReload(0xc00027a000, 0x0, 0xc010e5a6c0)
	/Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/game_events.go:285 +0x9c
github.com/markus-wa/demoinfocs-golang.(*Parser).handleGameEvent(0xc00027a000, 0xc001af2c40)
	/Users/mark/Projects/go/pkg/mod/github.com/markus-wa/demoinfocs-golang@v1.5.1/game_events.go:37 +0x16f
reflect.Value.call(0xdfa360, 0xc0003c4ec0, 0x13, 0xfb1c17, 0x4, 0xc000085f68, 0x1, 0x1, 0xc0000b77a8, 0xd8bfa8e72025e901, ...)
	/usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:460 +0x5f6
reflect.Value.Call(0xdfa360, 0xc0003c4ec0, 0x13, 0xc000085f68, 0x1, 0x1, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:321 +0xb4
github.com/markus-wa/godispatch.(*Dispatcher).Dispatch(0xc00027a020, 0xf728e0, 0xc001af2c40)
	/Users/mark/Projects/go/pkg/mod/github.com/markus-wa/godispatch@v1.1.0/dispatch.go:48 +0x24f
github.com/markus-wa/godispatch.(*Dispatcher).dispatchQueue(0xc00027a020, 0xc00035a000)
	/Users/mark/Projects/go/pkg/mod/github.com/markus-wa/godispatch@v1.1.0/dispatch.go:97 +0xf4
created by github.com/markus-wa/godispatch.(*Dispatcher).AddQueues
	/Users/mark/Projects/go/pkg/mod/github.com/markus-wa/godispatch@v1.1.0/dispatch.go:83 +0x183

marksamman · 2019-11-24T11:41:33Z

Demo file available here: https://www.dropbox.com/s/9w0fsx68go4yfry/mrec_19_11_16_37_56.dem?dl=0

markus-wa · 2019-11-24T14:21:51Z

Hmm, this is looking bad ... I hope my fix won't just end up suppressing things that should be parsed correctly.

From which service are these demos being recorded? (PopFlash, FaceIt etc.)

marksamman · 2019-11-24T14:24:41Z

It's part of the demo transmission pipeline on Esportal (https://beta.esportal.se/) running on servers using Sourcemod, so broken demo files are currently not uploaded to the service. We download demo files from servers over FTP after a match ends, extract chat logs using this package and upload both the demo file and the chat logs to cloud storage and mark demo file as available for download.

markus-wa · 2019-11-24T14:34:23Z

Hmm. Has there maybe also been any change besides the CS:GO update? For example in the way players connect to the server, game rules, bots, plugin changes/updates or anything of the sort that you're aware of?

Not trying to shift the blame as this is either way a bug in the library (since GOTV works), but just trying to figure out what might cause it. From what I can tell MM demos still seem to be doing fine for instance, even after the update.

marksamman · 2019-11-24T14:43:11Z

We updated to the latest version of Sourcemod recently (Wednesday), from "1.10.0.6432" to "1.11.0.6469". Other changes (we started tracking weapon hit accuracy and clutch attempts from our Sourcemod plugin) were at least a week before the issue started happening, so unlikely to be related.

markus-wa · 2019-11-24T15:02:46Z

Thanks. But yeah it doesn't look like that would be related.

Could you send me the following:

Demo from ~ 1 week ago that works
Demo from today/yesterday that works with v1.5.1 (not including my attempted fix) - if you have one

I will look into adding these plus the ones you already sent me to the regression suite (or at least some of them) once this is fixed.

markus-wa · 2019-11-24T15:16:28Z

One thing I'm observing in GOTV is that these players that are 'missing' are named 'unconnected' even though they are real players (judging by the movement etc.).

Could you have a look at the first two rounds of https://www.dropbox.com/s/9w0fsx68go4yfry/mrec_19_11_16_37_56.dem?dl=0 ? I see the knife round is 1v1 and the pistol round has 4 bots in each team and then the player connect.

I also translated some of the chat and it seems like something has gone wrong in the match setup (vad händer / what's happening).

Anyway, what I think I will do is try to handle these players as unconnected, similar to GOTV.

marksamman · 2019-11-25T09:52:11Z

Apologies for the late response, I don't have CS:GO installed and have tried to ask other people involved in Esportal development for more information but haven't received anything helpful yet unfortunately. We've had an issue reported since Nov 17 where some users are not firing a disconnect event in our Sourcemod plugin when they disconnect. Our plugin developer claims that the users are timing out and that the plugin isn't notified for an unknown reason. We haven't been able to address that issue yet. It could be that these users are also causing the unexpected data in the demo file, although the demo file of a match where such an issue happened was successfully processed: https://s3.eu-central-1.wasabisys.com/demo-production/1333267.dem

Here's a demo file that was successfully processed from Wednesday evening:
https://s3.eu-central-1.wasabisys.com/demo-production/1340697.dem

I'll revert the attempted fix and get you a demo file that works with v1.5.1 later today.

marksamman · 2019-11-25T11:44:08Z

Here's a demo that was processed without any issues using v1.5.1: https://s3.eu-central-1.wasabisys.com/demo-production/1349541.dem

we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

markus-wa · 2019-11-28T20:27:31Z

This should be fixed with v1.6.0-rc0 or PR #163. Please verify.

If it works I will merge to master and do a proper release.

PS: sorry for dropping the ball on this, was a hectic week at work.

markus-wa · 2019-11-28T21:17:47Z

one more thing @marksamman - is it ok if I add esportal.se to this list?

marksamman · 2019-11-28T21:45:41Z

It seems to work. Thank you!

one more thing @marksamman - is it ok if I add esportal.se to this list?

Yeah, that's OK :)

we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

markus-wa · 2019-11-28T21:59:03Z

Awesome, thanks!

And I've added the site to the list 😄

…#163) we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

markus-wa added the kind: bug label Nov 23, 2019

markus-wa mentioned this issue Nov 23, 2019

fix nil pointer dereference for valid demo #163

Merged

markus-wa added a commit that referenced this issue Nov 23, 2019

fix nil pointer dereference for valid demo (#162)

d70a67c

we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

markus-wa added a commit that referenced this issue Nov 23, 2019

fix nil pointer dereference for valid demo (#162)

4c8b109

we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

BestAwperEver mentioned this issue Nov 28, 2019

nil raw player inside bindNewPlayer() #165

Closed

markus-wa added a commit that referenced this issue Nov 28, 2019

fix nil pointer dereference for valid demo (#162)

bc4bf26

we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

markus-wa added a commit that referenced this issue Nov 28, 2019

fix nil pointer dereference for valid demo (#162)

138c28f

we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

markus-wa closed this as completed in #163 Nov 28, 2019

markus-wa added a commit that referenced this issue Nov 28, 2019

fix nil pointer dereference for valid demo (#162) (#163)

944a72d

we just assume it's a bot since all human players were parsed correctly in the demo where this problem was encountered.

markus-wa added the status: fixed / implemented label Nov 28, 2019

pbuzulan mentioned this issue Dec 18, 2020

runtime error when registering events of a demo file #258

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime error when parsing demo file #162

runtime error when parsing demo file #162

marksamman commented Nov 23, 2019

markus-wa commented Nov 23, 2019

marksamman commented Nov 24, 2019

marksamman commented Nov 24, 2019

marksamman commented Nov 24, 2019

markus-wa commented Nov 24, 2019

marksamman commented Nov 24, 2019

markus-wa commented Nov 24, 2019

marksamman commented Nov 24, 2019

markus-wa commented Nov 24, 2019

markus-wa commented Nov 24, 2019

marksamman commented Nov 25, 2019

marksamman commented Nov 25, 2019

markus-wa commented Nov 28, 2019 •

edited

markus-wa commented Nov 28, 2019

marksamman commented Nov 28, 2019

markus-wa commented Nov 28, 2019

runtime error when parsing demo file #162

runtime error when parsing demo file #162

Comments

marksamman commented Nov 23, 2019

markus-wa commented Nov 23, 2019

marksamman commented Nov 24, 2019

marksamman commented Nov 24, 2019

marksamman commented Nov 24, 2019

markus-wa commented Nov 24, 2019

marksamman commented Nov 24, 2019

markus-wa commented Nov 24, 2019

marksamman commented Nov 24, 2019

markus-wa commented Nov 24, 2019

markus-wa commented Nov 24, 2019

marksamman commented Nov 25, 2019

marksamman commented Nov 25, 2019

markus-wa commented Nov 28, 2019 • edited

markus-wa commented Nov 28, 2019

marksamman commented Nov 28, 2019

markus-wa commented Nov 28, 2019

markus-wa commented Nov 28, 2019 •

edited