Multiple log file for the same game

[chippydip]

@Crazometer reported the following:

I've checked that I've only got one copy of hearthlog running yet am getting occasional doubles. Note the identical timestamps on SOME games. Similar to the other user the counter increments by a seemingly random amount. I', running windows 8.1 if that helps

http://imgur.com/5TCBe1C

Nice program by the way!

This appears to be something else entirely, so I'm creating a new issue for it.

[chippydip]

Looking at the actual log files one contains only a subset of the messages from the other and has a starting timestamp 1 second later, which is what causes the duplication. I'll try to track down why this is happening, but it would also be helpful if @Crazometer or anyone else who is experiencing this issue could send me a log file to take a look at.

You should be able to find the log file in C:\Users\\AppData\Roaming\Hearth Log\log.txt (alternately, you can right-click the Hearth Log icon, select Show Log..., and then copy&paste the contents from there).

You can paste the contents into a new gist and link that here, or just send me the log directly (cfbradford@gmail.com).

Closing and reopening the Hearth Log app between games will result in smaller log files but may or may not have an impact on the issue. It would be most helpful to grab the log right after finishing a game in which this occurs to make it easier for me to pin-point the problem. It would also be helpful to include your timezone (so I can properly correlate timestamps in the log with server uploads) and your username on hearthlog.com

[jspri]

I realised that my networking setup may be a bit strange as I'm not too familiar with how winpcap operates. I have a virtual adapter which is bridged to my physical adapter because occasionally I virtualise. It could be possible that the hearthstone packets are being broadcast over two adaptors and captured twice. I'm unsure how that would correlate with the 1 second delay and incomplete logs though.

Upon disabling the bridge everything seemed to work properly. I played three games which all reported correctly.

https://gist.github.com/Crazometer/c05227017d3915b445be

Once the bridge was re-enabled I had a match not appear on the site at all (I conceded ->14:15 in the log) but the next two games worked fine.

https://gist.github.com/Crazometer/bc4ffd7df60f1b26c99b

I made a mistake in not keeping the original log file when things were going wrong but thought I'd try to get you a clean one. My guess is that there was something funky going on in the network settings that I incidentally fixed when playing around with the bridging. I had to do some basic troubleshooting (ran windows debug tool which said it rebound the stack) just to get connectivity back when I first disabled it.

I'll be sure to post back if I notice it happening in the future

My timezone is AEDT http://www.timeanddate.com/library/abbreviations/timezones/au/edt.html

[chippydip]

There's definitely something very strange going on there! I don't see any duplicate logs being created, but I do see what's causing the difference between the two versions.

The start of a logged game should look something like this:

14:15:16: 1387682116629004000 [192.168.1.6]:53004->[12.130.244.77]:1119 logging 14:15:17: pairing [12.130.244.77]:1119->[192.168.1.6]:53004 with [192.168.1.6]:53004->[12.130.244.77]:1119 14:15:17: 1387682116844074000 [192.168.1.6]:53004->[12.130.244.77]:1119 (168, 17) 14:15:17: 1387682117698838000 [192.168.1.6]:53004->[12.130.244.77]:1119 (113, 2) 14:15:18: 1387682118189860000 [192.168.1.6]:53004->[12.130.244.77]:1119 (114, 0) 14:15:18: 1387682118189860000 [192.168.1.6]:53004->[12.130.244.77]:1119 (16, 29)

The program only gets raw packets, so it not only needs to make sure to put them together in the correct order (if anything gets sent out of order), but it also has to match the two sides of a connection up. The first line of this snippet is detecting an outgoing packet from your machine to blizzard's, setting up a new connection. The second line detects the reply and pairs up the two connections.

The rest of the lines are logging messages on the paired connections. The numbers in parens indicate the type of message and the size of it's payload. 168 is the first message the client needs to send to the server to connect to a specific game and then 113 is sent to indicate that the client is ready to begin the game. The server then responds with a GameStarting message (114) and then a GameSetup message (16).

Now let's take a look at how most of your games start in the logs:

14:21:04: 1387682463492729000 [12.130.245.91]:1119->[192.168.1.6]:53216 logging 14:21:04: 1387682464810356000 [12.130.245.91]:1119->[192.168.1.6]:53216 (114, 0) 14:21:04: 1387682464810356000 [12.130.245.91]:1119->[192.168.1.6]:53216 (16, 29)

Notice that this log starts with a message from the server to the client and doesn't seem to ever pair with the other side of the connection. In addition, the log is missing the initial messages that the client sends to the server and instead starts with the server's reply. For some reason the logger seems to only be recording the messages from the server to the client, but isn't recording any of the packets from the client to the server.

I'm going to have to take a closer look at the code to see how that's even possible, but it does suggest that the duplicate log files are likely a result of a bridged network connection. It appears that one full log may have been recorded on one interface while another bridged interface recorded only half the conversation. Normally this probably wouldn't even be noticeable since one log would just overwrite the other. The logs are saved using the time-stamp of the first recorded message, though, so if the clock happens to roll over to the next second between when the client sends the first message and when the first server response arrives it will result in a different file-name and duplicate logs once they are uploaded.

So, it seem like there are several interesting corner-cases here that the logger needs to work around. Interestingly, the first example was the only one that looked correct in that set of logs and it was for the game that was never uploaded, so there might be something else going on there as well.

[jspri]

Do the upload files mean anything to you? I could provide those duplicates to you if you wish.