search

hippich / Bitcoin-Poker-Room

Sources for Bitcoin Poker Room.
http://betco.in
Other
132 stars 87 forks source link

Table ends up in crashed state #84

Closed hippich closed 13 years ago

hippich commented 13 years ago

Summary (full log attached)

Hand 262007 starts. Player 11110 (theFED) is included as part of the player
list at the start of the hand in position 5 (he had just played in the previous
hand 262006):

2011-07-17 06:59:38+0000 [-] PokerTable?: Dealing hand Issgar 4/262007
2011-07-17 06:59:38+0000 [-] [Server]11661? Dealing Hold'em hand number 262007
2011-07-17 06:59:38+0000 [-] [Server]11661? player list: [9322, 10455, 8904, 11098, 9822, 11110, 11251]

Player 11110 posts the small blind of 50 during the blind and antes round:

2011-07-17 06:59:38+0000 [-] PokerTable?: Dealing hand Issgar 4/262007
2011-07-17 06:59:38+0000 [-] [Server]11661? Dealing Hold'em hand number 262007
2011-07-17 06:59:38+0000 [-] [Server]11661? player list: [9322, 10455, 8904, 11098, 9822, 11110, 11251]
2011-07-17 06:59:38+0000 [-] [Server]11661? changing state end => blindAnte
2011-07-17 06:59:38+0000 [-] [Server]11661? player 11110 pays blind 50/0
2011-07-17 06:59:38+0000 [-] [Server]11661? player 11251 pays blind 100/0

Then he rebuys 208 chips and sits in:

2011-07-17 06:59:46+0000 [HTTPChannel,43725,127.0.0.1] PokerTable?: broadcast[8904, 10455, 11098, 9822, 11234, 11110, 9322, 11251] type = POKER_REBUY(85) serial = 11110 game_id = 11661 amount = 208
2011-07-17 06:59:46+0000 [HTTPChannel,43725,127.0.0.1] PokerTable?: broadcast[8904, 10455, 11098, 9822, 11234, 11110, 9322, 11251] type = POKER_SIT(75) serial = 11110 game_id = 11661

So does this mean he was sitting out when he posted the blind of 50? And how was
he able to rebuy if he already posted the small blind?

After all blinds and antes have been posted, player 11110 is no longer in the
players list, and when the preflop round starts, he is not dealt cards. The log
indicates he is waiting to play (reason=first_round).

2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] [Server]11661? player list: [9322, 10455, 8904, 9822, 11251]
2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] [Server]11661? changing state blindAnte => pre-flop
2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] [Server]11661? player 9322 cards: Th Ac
2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] [Server]11661? player 10455 cards: Jh Qh
2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] [Server]11661? player 8904 cards: Qc 5c
2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] [Server]11661? player 9822 cards: 8d 7c
2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] [Server]11661? player 11251 cards: 2c 6d
2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] [Server]11661? new round pre-flop

2011-07-17 06:59:48+0000 [HTTPChannel,43868,127.0.0.1] PokerTable?: broadcast[8904, 10455, 11098, 9822, 11234, 11110, 9322, 11251] type = POKER_WAIT_FOR(103) serial = 11110 game_id = 11661 reason = first_round

Since player 11110 posted the small blind, shouldn't he be in the players list
and have been dealt cards?

During the preflop round player 11110 joins the table:

2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] PokerAvatar?: sendPacket(11110): type = POKER_TABLE(73)
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] id = 11661, name = Issgar 4, variant = holdem, betting_structure = .50-1-no-limit, seats = 10, average_pot = 4208, hands_per_hour = 40, percent_flop = 37, players = 8, observers = 3, waiting = 0, player_timeout = 30, muck_timeout = 5, currency_serial = 1, skin = default, tourney_serial = 0, reason = TableJoin?

I did not see any mention in the log about him leaving. Could he have been
disconnected?

When he joins, packets are sent to him as follows (see class
PacketPokerTableJoin? in pokernetwork/pokerpackets.py):

(0) In the case that the join is completely successful, or if the player

had already joined the table, the following packets are sent:

PACKET_POKER_TABLE
PACKET_POKER_BATCH_MODE
for each player in the game:

PACKET_POKER_PLAYER_ARRIVE

if the player is playing:

PACKET_POKER_PLAYER_CHIPS

if the player is sit:

PACKET_POKER_SIT

PACKET_POKER_SEATS
if the game is running:

the exact packet sequence that lead to the current state
of the game. Varies according to the game.

PACKET_POKER_STREAM_MODE

Note clearly that if the player had already previously joined the
table, the packets above will be sent as if the player just joined.
However, in that case, the packet will have no side effect.

When rebroadcasting the start of the hand to player 11110, an exception is raised:

2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] PokerAvatar?: sendPacket(11110): type = POKER_START(66) serial = 0 game_id = 11661 hands_count = 1209, time = 398169, hand_serial = 262007, level = 0
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] [11110]11661? Dealing Hold'em hand number 262007
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] [11110]11661? changing state null => blindAnte
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] [11110]11661? initialisation turn 262007 ... finished
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] PokerAvatar?: sendPacket(11110): type = POKER_POSITION(54) game_id = 11661, position = 5, serial = 0
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] PokerAvatar?: Traceback (most recent call last):
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokeravatar.py", line 328, in sendPacket
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] self.explain.explain(packet)
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokerexplain.py", line 618, in explain
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] position_changed = serial_in_position != game.getSerialInPosition()
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokerengine/pokergame.py", line 3354, in getSerialInPosition
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] return self.player_list[self.position]
2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] IndexError?: list index out of range

Notice that position = 5 is the position of player 11110 at the start of the
hand. The possible cause of this exception may be described in the comment for
sit(self, serial) in pokergame.py:

# Rationale of player.sit_out_next_turn == False
# This condition happens when the player sitout + sit
# while not having the position during the blind/ante round it.
# In this particular case, instead of instructing her to wait
# for the first round, she sits back. This is important because
# she was included in the player list at the begining of the turn.
# If she is marked wait_for = "first_round", she will be removed
# from the player list at the end of the blind/ante round, which
# is exactly the opposite of what we want.

Perhaps player 11110 was marked wait_for="first_round" and was removed from the
player list at the end of the blind/ante round?

There is another exception that is raised after the POKER_STREAM_MODE packet is
sent:

2011-07-17 07:00:00+0000 [HTTPChannel,43863,127.0.0.1] PokerAvatar?: sendPacket(11110): type = POKER_STREAM_MODE(104) serial = 0 game_id = 11661
2011-07-17 07:00:01+0000 [HTTPChannel,43864,127.0.0.1] PokerService?: *ERROR* avatar PokerAvatar? serial = 11110, name = theFED is not in the list of known avatars

The cause for this is probably the same as the cause for the IndexError?.

Throughout the hand there are many 'unable to update position' errors:

2011-07-17 07:00:10+0000 [HTTPChannel,43846,127.0.0.1] [Server]11661? ERROR: unable to update position

During the flop round, player 11110 joins the table again:

2011-07-17 07:00:36+0000 [HTTPChannel,43879,127.0.0.1] PokerAvatar?: sendPacket(11177): type = POKER_TABLE(73)
2011-07-17 07:00:36+0000 [HTTPChannel,43879,127.0.0.1] id = 11683, name = Syfar 1, variant = holdem, betting_structure = 10-20-no-limit, seats = 10, average_pot = 35948, hands_per_hour = 120, percent_flop = 75, players = 1, observers = 0, waiting = 0, player_timeout = 180, muck_timeout = 5, currency_serial = 1, skin = default, tourney_serial = 0, reason = TableJoin?

The same IndexError? and "avatar is not in the list of know avatars" errors occur
when rebroadcasting the hand.

Before the hand ends, player 11110 leaves the table:

2011-07-17 07:00:57+0000 [-] [Server]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] PokerAvatar?: sendPacket(11110): type = POKER_PLAYER_LEAVE(81) serial = 11110 game_id = 11661 seat = 7
2011-07-17 07:00:57+0000 [-] [11110]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] PokerTable?: broadcast[8904, 10455, 11098, 9822, 11234, 9322, 11251] type = POKER_PLAYER_LEAVE(81) serial = 11110 game_id = 11661 seat = 7
2011-07-17 07:00:57+0000 [-] [8904]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] [10455]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] [11098]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] [9822]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] [11234]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] [9322]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] [11251]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] 11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] [24]11661? removing player 11110 from game
2011-07-17 07:00:57+0000 [-] PokerService?: leavePlayer UPDATE user2money,user2table,pokertables SET user2money.amount = user2money.amount + user2table.money + user2table.bet WHERE user2money.user_serial = user2table.user_serial AND user2money.currency_serial = pokertables.currency_serial AND pokertables.serial = 11661 AND user2table.table_serial = 11661 AND user2table.user_serial = 11110
2011-07-17 07:00:57+0000 [-] PokerService?: leavePlayer DELETE from user2table WHERE user_serial = 11110 AND table_serial = 11661

Finally after the hand is completed, there is an error when distributing the
rake:

2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] PokerResource?: *ERROR* (x-forwarded-for:71.202.181.6) Traceback (most recent call last):
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 213, in addCallbacks
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] self._runCallbacks()
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 371, in _runCallbacks
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] self.result = callback(self.result, *args, **kw)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokersite.py", line 237, in <lambda>
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] deferred.addCallback(lambda result: self.deferRender(request, jsonp, packet, data))
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokersite.py", line 248, in deferRender
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] d = defer.maybeDeferred(session.avatar.handleDistributedPacket, request, packet, data)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] --- <exception caught here> ---
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 117, in maybeDeferred
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] result = f(*args, **kw)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokeravatar.py", line 424, in handleDistributedPacket
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] return self.handlePacketDefer(packet)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokeravatar.py", line 483, in handlePacketDefer
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] self.handlePacketLogic(packet)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokeravatar.py", line 866, in handlePacketLogic
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] game.fold(packet.serial)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokerengine/pokergame.py", line 2042, in fold
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] self.talked(serial)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokerengine/pokergame.py", line 2245, in talked
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] self.muckState(WON_FOLD)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokerengine/pokergame.py", line 1723, in muckState
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] self.setRakedAmount(self.rake.getRake(self))
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokerengine/pokergame.py", line 1751, in setRakedAmount
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] self.historyAdd("rake", rake, self.getRakeContributions())
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokerengine/pokergame.py", line 1770, in getRakeContributions
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] return self.distributeRake(rake, total, serial2share)
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokerengine/pokergame.py", line 1789, in distributeRake
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] contribution += self.getPlayer(serial).dead
2011-07-17 07:01:13+0000 [HTTPChannel,43862,127.0.0.1] exceptions.AttributeError?: 'NoneType?' object has no attribute 'dead'

PokerGame?.getPlayer(serial) returns None -- perhaps because player 11110 left
the table, or was not part of the players list?

At this point the table is in a "crashed" state in the sense that play is
stopped. A new hand is not being dealt, and when observers join the table they
see hand #262007 being replayed.

hippich commented 13 years ago

Raw log - http://pastebin.com/raw.php?i=853Bg8DW

hippich commented 13 years ago

Today another table ended in crashed state.

Here is actual error:

2011-07-29 04:19:29+0000 [HTTPChannel,1596,127.0.0.1] [Server][PokerGame 14290] ERROR: unable to update position

And a little bit later this happens:

2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] [11215][PokerGame 14290] Dealing Hold'em hand number 297509 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] PokerAvatar: Traceback (most recent call last): 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokeravatar.py", line 328, in sendPacket 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] self.explain.explain(packet) 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokerexplain.py", line 323, in explain 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] game.beginTurn(packet.hand_serial) 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokerengine/pokergame.py", line 982, in beginTurn 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] if not self.buildPlayerList(True): 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] File "/usr/lib/python2.6/dist-packages/pokernetwork/pokergameclient.py", line 58, in buildPlayerList 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] assert self.player_list == filter(lambda x: self.serial2player[x].isSit(), self.player_list) 2011-07-29 04:19:40+0000 [HTTPChannel,1516,127.0.0.1] AssertionError

Here is full log - http://ubuntuone.com/p/170Y/

anisoptera commented 13 years ago

Thanks to @gg for help on the repro.