Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Board position can be changed while other commands are executed #156

Closed
herzbube opened this issue May 17, 2013 · 6 comments

Comments

Projects
None yet
1 participant
@herzbube
Copy link
Owner

commented May 17, 2013

In certain situations it is possible that the user is allowed to change the board position while other commands are executed by CommandProcessor. These "rogue" board position changes must be prevented because they result in the application state being corrupted, which in turn leads to weird behaviour and/or crashes. It is likely that these "rogue" board position changes are the root cause for the problems reported in issues #90, #128 and #129.

The problem was identified when analyzing the log files inside two bug reports that were sent by users affected by issue #90. In the first case the problem is reproducible and an in-depth analysis follows further down. In the second case I was unable to reproduce the problem, but with the knowledge from the first case the log file analysis clearly shows where the "rogue" board position change occurs.

Steps to reproduce the problem in the first case (mentioned above), on the iPhone:

  1. Start a new game
  2. Play a few moves until the computer takes substantial time to compute its move
  3. Place the finger on the board with the intention to place a stone
  4. When the cross-hair stone is on an intersection where it is legal to play, lift the finger to place the stone
  5. With a second finger immediately hit one of the board position navigation buttons below the board, while the buttons are still enabled. Note that the timing is crucial: One must be very quick to hit a button at the right time.

What happens now is the following:

  • Little Go submits a genmove GTP command
  • Instead of waiting for a response to genmove, Little Go starts to process the board position change
  • When Little Go tries to sync the GTP engine with the new board position, it is blocked because the engine still processes the genmove command. Internally, however, Little Go has already changed its board position.
  • When Little Go receives the response to genmove it generates a new GoMove. This is where the internal state of Little Go becomes corrupt
    • The GoPoint and GoBoardRegion objects represent the state of the current board position
    • When the new GoMove is created, it changes the state of those objects so that they no longer represent the current board position
  • What happens next depends on the user's actions, but disaster is almost inevitable. The only way how the situation can be salvaged is when the user starts a new game, or loads a game from the archive, thus destroying the corrupt GoPoint and GoBoardRegion objects

Two possible outcomes have been observed so far:

  • The application crashes when an exception is thrown because the corruption is detected. This typically happens when the board position is changed.
  • ComputerPlayCommand finds that the move played by the computer player is illegal. The error handling code introduced for issue #90 then comes into play and at least helps the user to find a graceful way out of the situation.

@ghost ghost assigned herzbube May 17, 2013

@herzbube

This comment has been minimized.

Copy link
Owner Author

commented May 17, 2013

The steps to reproduce the issue in the original bug report seem to be rather far-fetched, i.e. a user would have to use two hands to deliberately trigger the bug. However, after analyzing the log files sent to me by a user who was affected by the problem, I have come to the conclusion that a user can inadvertently trigger the bug like this:

  • The user wants to place a stone in the lower part of the board (e.g. at intersection G2 on a 19x19 board)
  • To do that when StoneDistanceFromFingertip is >0, it is inevitable that the fingertip travels outside of the board and over the toolbar with the board position navigation buttons
  • When the user lifts the fingertip away from the screen to conclude the gesture, it is possible that one of the navigation button may be inadvertently tapped, thus triggering the bug

Although I have not been able to reproduce this myself on my iPhone 3GS, I can imagine how this could happen when the fingertip is not lifted away cleanly and immediately.

@herzbube

This comment has been minimized.

Copy link
Owner Author

commented May 17, 2013

Here is an excerpt from a log file that I received from an affected user, with annotations that explain how the bug manifests itself. The game is played on the iPhone, on a 19x19 board, the user plays black, the computer plays white. Something more than 90 moves have already been played at the time the log excerpt starts.

This is the last move by black before the problem starts: B G2

2013/05/12 18:28:46:710  Executing DiscardAndPlayCommand(0x1f9d0cf0): name = DiscardAndPlayCommand, undoable = 0
2013/05/12 18:28:46:710  PlayView, longRunningActionStarts, new value for self.actionsInProgress = 1
2013/05/12 18:28:46:711  Executing PlayMoveCommand(0x1f9c4730): name = PlayMoveCommand, undoable = 0
2013/05/12 18:28:46:732  Submitting GtpCommand(0x1fb2ed30): play B G2
2013/05/12 18:28:46:733  Command execution succeeded (PlayMoveCommand(0x1f9c4730): name = PlayMoveCommand, undoable = 0)
2013/05/12 18:28:46:733  PlayView, longRunningActionEnds, new value for self.actionsInProgress = 0
2013/05/12 18:28:46:734  Command execution succeeded (DiscardAndPlayCommand(0x1f9d0cf0): name = DiscardAndPlayCommand, undoable = 0)
2013/05/12 18:28:46:735  Deallocating DiscardAndPlayCommand(0x1f9d0cf0): name = DiscardAndPlayCommand, undoable = 0
2013/05/12 18:28:46:739  SymbolsLayerDelegate is drawing
2013/05/12 18:28:46:742  StonesLayerDelegate is drawing
2013/05/12 18:28:46:825  Received GtpResponse(0x1ed703d0): =  (to GtpCommand(0x1fb2ed30): play B G2)
2013/05/12 18:28:46:826  Executing BackupGameCommand(0x1f9a75b0): name = BackupGameCommand, undoable = 0
2013/05/12 18:28:46:827  BackupGameCommand(0x1f9a75b0): Saving NSCoding archive
2013/05/12 18:28:47:720  BackupGameCommand(0x1f9a75b0): Saving current game to .sgf file
2013/05/12 18:28:47:721  BackupGameCommand(0x1f9a75b0): Working directory changed to /var/mobile/Applications/69AA6D46-753E-4DDD-843B-1AC402651FCB/Library/Application Support
2013/05/12 18:28:47:721  Submitting GtpCommand(0x1ed72f10): savesgf backup.sgf
2013/05/12 18:28:47:748  Received GtpResponse(0x1fc74b30): =  (to GtpCommand(0x1ed72f10): savesgf backup.sgf)
2013/05/12 18:28:47:748  BackupGameCommand(0x1f9a75b0): Working directory changed to /
2013/05/12 18:28:47:749  Command execution succeeded (BackupGameCommand(0x1f9a75b0): name = BackupGameCommand, undoable = 0)

Here the computer starts to generate its move for white

2013/05/12 18:28:47:749  Executing ComputerPlayMoveCommand(0x1f9d0810): name = ComputerPlayMoveCommand, undoable = 0
2013/05/12 18:28:47:749  Submitting GtpCommand(0x1f9e73c0): genmove W
2013/05/12 18:28:47:762  Command execution succeeded (ComputerPlayMoveCommand(0x1f9d0810): name = ComputerPlayMoveCommand, undoable = 0)
2013/05/12 18:28:47:763  Deallocating BackupGameCommand(0x1f9a75b0): name = BackupGameCommand, undoable = 0
2013/05/12 18:28:47:764  Deallocating PlayMoveCommand(0x1f9c4730): name = PlayMoveCommand, undoable = 0

This is where the problems start: ChangeBoardPositionCommand should not
be possible while the computer is thinking about its move.

2013/05/12 18:28:47:766  Executing ChangeBoardPositionCommand(0x1fb4ab40): name = ChangeBoardPositionCommand, undoable = 0
2013/05/12 18:28:47:766  ChangeBoardPositionCommand(0x1fb4ab40): newBoardPosition = 92, currentBoardPosition = 93, numberOfBoardPositions = 94
2013/05/12 18:28:47:766  PlayView, longRunningActionStarts, new value for self.actionsInProgress = 1
2013/05/12 18:28:47:767  Executing SyncGTPEngineCommand(0x1ede3f40): name = SyncGTPEngineCommand, undoable = 0

Here SyncGTPEngineCommand is blocked since the GTP engine still processes
the "genmove" command

2013/05/12 18:28:47:767  Submitting GtpCommand(0x1f932680): clear_board

Here the GTP engine's response to "genmove" is received, but the response
target (ComputerPlayMoveCommand) cannot be notified because the main
thread is still blocked by SyncGTPEngineCommand.

2013/05/12 18:28:56:642  Received GtpResponse(0x1f99b810): = G3 (to GtpCommand(0x1f9e73c0): genmove W)

Now that the "genmove" command has been processed, the GTP engine starts
to process the commands that SyncGTPEngineCommand submits

2013/05/12 18:28:56:646  Received GtpResponse(0x1ed4b990): =  (to GtpCommand(0x1f932680): clear_board)

Here the GTP engine "forgets" about the move "W G3" that it just generated

2013/05/12 18:28:56:655  Submitting GtpCommand(0x1f9e7990): gogui-play_sequence B Q15 W D16 B Q5 W D4 B O3 W B12 B O16 W R8 B R11 W G5 B L4 W G12 B C8 W K14 B L9 W J10 B C6 W J2 B K2 W N11 B O12 W S7 B S6 W R6 B S5 W T6 B S9 W T5 B R5 W Q6 B P6 W R3 B Q7 W R7 B Q8 W Q9 B T4 W T7 B S3 W P5 B O7 W O6 B P7 W O5 B R9 W N7 B P9 W K3 B L3 W S2 B T8 W L2 B M2 W K1 B P4 W Q4 B Q2 W B4 B B10 W L5 B K4 W E9 B E7 W F8 B F7 W G7 B E8 W J5 B J3 W H3 B K2 W J4 B L1 W K5 B M5 W M6 B N5 W N6 B O4 W N4 B M4 W N3 B N2 W P3 B O2 W R4 B S8 W D13 B H2 W K3 B J1 W J3
2013/05/12 18:28:56:703  Received GtpResponse(0x1f9a41d0): =  (to GtpCommand(0x1f9e7990): gogui-play_sequence B Q15 W D16 B Q5 W D4 B O3 W B12 B O16 W R8 B R11 W G5 B L4 W G12 B C8 W K14 B L9 W J10 B C6 W J2 B K2 W N11 B O12 W S7 B S6 W R6 B S5 W T6 B S9 W T5 B R5 W Q6 B P6 W R3 B Q7 W R7 B Q8 W Q9 B T4 W T7 B S3 W P5 B O7 W O6 B P7 W O5 B R9 W N7 B P9 W K3 B L3 W S2 B T8 W L2 B M2 W K1 B P4 W Q4 B Q2 W B4 B B10 W L5 B K4 W E9 B E7 W F8 B F7 W G7 B E8 W J5 B J3 W H3 B K2 W J4 B L1 W K5 B M5 W M6 B N5 W N6 B O4 W N4 B M4 W N3 B N2 W P3 B O2 W R4 B S8 W D13 B H2 W K3 B J1 W J3)
2013/05/12 18:28:56:704  Command execution succeeded (SyncGTPEngineCommand(0x1ede3f40): name = SyncGTPEngineCommand, undoable = 0)
2013/05/12 18:28:56:704  Executing BackupGameCommand(0x1edd8e30): name = BackupGameCommand, undoable = 0
2013/05/12 18:28:56:705  BackupGameCommand(0x1edd8e30): Saving NSCoding archive
2013/05/12 18:28:57:253  Command execution succeeded (BackupGameCommand(0x1edd8e30): name = BackupGameCommand, undoable = 0)

PlayView does not yet draw because the main thread is still busy
processing ComputerPlayMoveCommand

2013/05/12 18:28:57:254  PlayView, longRunningActionEnds, new value for self.actionsInProgress = 0
2013/05/12 18:28:57:256  Command execution succeeded (ChangeBoardPositionCommand(0x1fb4ab40): name = ChangeBoardPositionCommand, undoable = 0)
2013/05/12 18:28:57:258  Deallocating BackupGameCommand(0x1edd8e30): name = BackupGameCommand, undoable = 0
2013/05/12 18:28:57:261  Deallocating SyncGTPEngineCommand(0x1ede3f40): name = SyncGTPEngineCommand, undoable = 0
2013/05/12 18:28:57:262  Deallocating ChangeBoardPositionCommand(0x1fb4ab40): name = ChangeBoardPositionCommand, undoable = 0

Here the main thread finally notifies ComputerPlayMoveCommand of the
response to the "genmove" command. ComputerPlayMoveCommand plays the move
using GoGame (this is not logged) and subsequently executes
BackupGameCommand (we know that it must be ComputerPlayMoveCommand
executing BackupGameCommand because the .sgf file is being saved).
The bad thing about GoGame playing the move is that the state of the
GoPoint object for intersection G3, and the state of the surrounding
GoBoardRegions objects, is being changed. They no longer represent
the state of the current board position (which is after "W J3"). From
here onwards, Little Go is in a corrupt state!

2013/05/12 18:28:57:288  Executing BackupGameCommand(0x1f940ea0): name = BackupGameCommand, undoable = 0
2013/05/12 18:28:57:290  BackupGameCommand(0x1f940ea0): Saving NSCoding archive
2013/05/12 18:28:57:930  BackupGameCommand(0x1f940ea0): Saving current game to .sgf file
2013/05/12 18:28:57:932  BackupGameCommand(0x1f940ea0): Working directory changed to /var/mobile/Applications/69AA6D46-753E-4DDD-843B-1AC402651FCB/Library/Application Support
2013/05/12 18:28:57:943  Submitting GtpCommand(0x1fb168b0): savesgf backup.sgf
2013/05/12 18:28:57:959  Received GtpResponse(0x1edecc90): =  (to GtpCommand(0x1fb168b0): savesgf backup.sgf)
2013/05/12 18:28:57:961  BackupGameCommand(0x1f940ea0): Working directory changed to /
2013/05/12 18:28:57:962  Command execution succeeded (BackupGameCommand(0x1f940ea0): name = BackupGameCommand, undoable = 0)
2013/05/12 18:28:57:984  Deallocating BackupGameCommand(0x1f940ea0): name = BackupGameCommand, undoable = 0

Here ComputerPlayMoveCommand does not trigger another "genmove" because
GoGame's isComputerPlayersTurn returns false. It does this because it
looks at self.lastMove and not at the current board position.

2013/05/12 18:28:57:986  Deallocating ComputerPlayMoveCommand(0x1f9d0810): name = ComputerPlayMoveCommand, undoable = 0

Now the main thread is finally free for drawing

2013/05/12 18:28:58:003  SymbolsLayerDelegate is drawing
2013/05/12 18:28:58:005  StonesLayerDelegate is drawing

At this point, the user sees the old board position after "W J3". He does
not see his move "B G2", nor the computer's move "W G3". The user now
repeats his move "B G2". We can assume that a DiscardFutureMovesAlert
has been shown, although that is not logged.

2013/05/12 18:29:04:884  Executing DiscardAndPlayCommand(0x1f9b0c10): name = DiscardAndPlayCommand, undoable = 0
2013/05/12 18:29:04:885  PlayView, longRunningActionStarts, new value for self.actionsInProgress = 1

Although not shown in the log, DiscardAndPlayCommand has just discarded
the last two moves "B G2" and "W G3" from GoMoveModel. Discarding those
moves has not changed anything about the corrupt state of the GoPoint
object for intersection G3 and its surrounding GoBoardRegion objects.

2013/05/12 18:29:04:885  Executing PlayMoveCommand(0x1f9f5ef0): name = PlayMoveCommand, undoable = 0
2013/05/12 18:29:04:931  Submitting GtpCommand(0x1f9ab500): play B G2
2013/05/12 18:29:04:932  Command execution succeeded (PlayMoveCommand(0x1f9f5ef0): name = PlayMoveCommand, undoable = 0)
2013/05/12 18:29:04:932  PlayView, longRunningActionEnds, new value for self.actionsInProgress = 0
2013/05/12 18:29:04:933  Command execution succeeded (DiscardAndPlayCommand(0x1f9b0c10): name = DiscardAndPlayCommand, undoable = 0)
2013/05/12 18:29:04:934  Deallocating DiscardAndPlayCommand(0x1f9b0c10): name = DiscardAndPlayCommand, undoable = 0
2013/05/12 18:29:04:952  SymbolsLayerDelegate is drawing
2013/05/12 18:29:04:953  StonesLayerDelegate is drawing
2013/05/12 18:29:05:036  Received GtpResponse(0x1f9eafa0): =  (to GtpCommand(0x1f9ab500): play B G2)
2013/05/12 18:29:05:037  Executing BackupGameCommand(0x1f99d6f0): name = BackupGameCommand, undoable = 0
2013/05/12 18:29:05:039  BackupGameCommand(0x1f99d6f0): Saving NSCoding archive
2013/05/12 18:29:05:650  BackupGameCommand(0x1f99d6f0): Saving current game to .sgf file
2013/05/12 18:29:05:651  BackupGameCommand(0x1f99d6f0): Working directory changed to /var/mobile/Applications/69AA6D46-753E-4DDD-843B-1AC402651FCB/Library/Application Support
2013/05/12 18:29:05:652  Submitting GtpCommand(0x1fb107c0): savesgf backup.sgf
2013/05/12 18:29:05:669  Received GtpResponse(0x1fb215c0): =  (to GtpCommand(0x1fb107c0): savesgf backup.sgf)
2013/05/12 18:29:05:670  BackupGameCommand(0x1f99d6f0): Working directory changed to /
2013/05/12 18:29:05:672  Command execution succeeded (BackupGameCommand(0x1f99d6f0): name = BackupGameCommand, undoable = 0)

Here the computer repeats his earlier move "W G3". Because of the corrupt
state of the GoPoint object for intersection G3, Little Go now thinks that
the move is illegal - BANG!

2013/05/12 18:29:05:673  Executing ComputerPlayMoveCommand(0x1fc7ea70): name = ComputerPlayMoveCommand, undoable = 0
2013/05/12 18:29:05:674  Submitting GtpCommand(0x1f9b3910): genmove W
2013/05/12 18:29:05:714  Command execution succeeded (ComputerPlayMoveCommand(0x1fc7ea70): name = ComputerPlayMoveCommand, undoable = 0)
2013/05/12 18:29:05:717  Deallocating BackupGameCommand(0x1f99d6f0): name = BackupGameCommand, undoable = 0
2013/05/12 18:29:05:717  Deallocating PlayMoveCommand(0x1f9f5ef0): name = PlayMoveCommand, undoable = 0
2013/05/12 18:29:13:072  Received GtpResponse(0x1f999730): = G3 (to GtpCommand(0x1f9b3910): genmove W)
2013/05/12 18:29:24:405  Executing GenerateDiagnosticsInformationFileCommand(0x1fb0ff40): name = GenerateDiagnosticsInformationFileCommand, undoable = 0
2013/05/12 18:29:24:405  GenerateDiagnosticsInformationFileCommand(0x1fb0ff40): Creating folder /private/var/mobile/Applications/69AA6D46-753E-4DDD-843B-1AC402651FCB/tmp/littlego-bugreport
2013/05/12 18:29:24:451  GenerateDiagnosticsInformationFileCommand(0x1fb0ff40): Writing in-memory objects to file
2013/05/12 18:29:25:306  GenerateDiagnosticsInformationFileCommand(0x1fb0ff40): Writing user defaults to file
2013/05/12 18:29:25:378  GenerateDiagnosticsInformationFileCommand(0x1fb0ff40): Saving current game to .sgf file
2013/05/12 18:29:25:379  Submitting GtpCommand(0x1fb11180): savesgf currentgame.sgf
2013/05/12 18:29:25:400  Received GtpResponse(0x1fc639a0): =  (to GtpCommand(0x1fb11180): savesgf currentgame.sgf)
2013/05/12 18:29:25:401  GenerateDiagnosticsInformationFileCommand(0x1fb0ff40): Making screen shot of Play view
2013/05/12 18:29:25:988  GenerateDiagnosticsInformationFileCommand(0x1fb0ff40): Writing result of 'showboard' GTP command to file
2013/05/12 18:29:25:989  Submitting GtpCommand(0x1fb2d310): showboard
2013/05/12 18:29:26:005  Received GtpResponse(0x1fb16dd0): = 
   A B C D E F G H J K L M N O P Q R S T 
19 . . . . . . . . . . . . . . . . . . . 19
18 . . . . . . . . . . . . . . . . . . . 18
17 . . . . . . . . . . . . . . . . . . . 17
16 . . . O . . . . . + . . . X . + . . . 16
15 . . . . . . . . . . . . . . . X . . . 15
14 . . . . . . . . . O . . . . . . . . . 14
13 . . . O . . . . . . . . . . . . . . . 13
12 . O . . . . O . . . . . . X . . . . . 12
11 . . . . . . . . . . . . O . . . X . . 11
10 . X . + . . . . O + . . . . . + . . . 10
 9 . . . . O . . . . . X . . . X O X X . 9
 8 . . X . X O . . . . . . . . . X . X X 8
 7 . . . . X X O . . . . . O X X X . . . 7
 6 . . X . . . . . . . . O O O X . . X . 6
 5 . . . . . . O . O O O X X O O X X X . 5
 4 . O . O . . . . O X X X O X X O O . X 4
 3 . . . . . . O O O O X . O X O . O X . 3
 2 . . . . . . X X O X . X X X . X . O . 2   
 1 . . . . . . . . X . X . . . . . . . . 1   B to play
   A B C D E F G H J K L M N O P Q R S T  (to GtpCommand(0x1fb2d310): showboard)
2013/05/12 18:29:26:021  GenerateDiagnosticsInformationFileCommand(0x1fb0ff40): Zipping log files
@herzbube

This comment has been minimized.

Copy link
Owner Author

commented May 18, 2013

Here is an excerpt from another log file that I received from a different user. The game is played on the iPad, so the situation when the fatal ChangeBoardPositionCommand is executed is different from the iPhone case.

This is the last move by black before the problem starts: B D2

2013/05/17 03:19:34:424  Executing DiscardAndPlayCommand(0x1f297300): name = DiscardAndPlayCommand, undoable = 0
2013/05/17 03:19:34:424  PlayView, longRunningActionStarts, new value for self.actionsInProgress = 1
2013/05/17 03:19:34:424  Executing PlayMoveCommand(0x1f073b70): name = PlayMoveCommand, undoable = 0
2013/05/17 03:19:34:432  Submitting GtpCommand(0x1f24a3f0): play B D2
2013/05/17 03:19:34:432  Command execution succeeded (PlayMoveCommand(0x1f073b70): name = PlayMoveCommand, undoable = 0)
2013/05/17 03:19:34:434  PlayView, longRunningActionEnds, new value for self.actionsInProgress = 0
2013/05/17 03:19:34:434  Received GtpResponse(0x1f3761a0): =  (to GtpCommand(0x1f24a3f0): play B D2)
2013/05/17 03:19:34:444  Command execution succeeded (DiscardAndPlayCommand(0x1f297300): name = DiscardAndPlayCommand, undoable = 0)

This is where the problem starts: ChangeBoardPositionCommand should not be
possible when immediately afterwards a ComputerPlayMoveCommand is executed.

2013/05/17 03:19:34:444  Executing ChangeBoardPositionCommand(0x1f24d170): name = ChangeBoardPositionCommand, undoable = 0
2013/05/17 03:19:34:444  ChangeBoardPositionCommand(0x1f24d170): newBoardPosition = 25, currentBoardPosition = 26, numberOfBoardPositions = 27
2013/05/17 03:19:34:444  PlayView, longRunningActionStarts, new value for self.actionsInProgress = 1
2013/05/17 03:19:34:445  Executing SyncGTPEngineCommand(0x1f293cf0): name = SyncGTPEngineCommand, undoable = 0
2013/05/17 03:19:34:445  Submitting GtpCommand(0x1f231210): clear_board
2013/05/17 03:19:34:447  Received GtpResponse(0x1f3795f0): =  (to GtpCommand(0x1f231210): clear_board)
2013/05/17 03:19:34:447  Submitting GtpCommand(0x1f27ab90): fixed_handicap 9
2013/05/17 03:19:34:450  Received GtpResponse(0x1f25b940): =  (to GtpCommand(0x1f27ab90): fixed_handicap 9)
2013/05/17 03:19:34:451  Submitting GtpCommand(0x1f38a930): gogui-play_sequence W O2 B E5 W D5 B E6 W C4 B F7 W D3 B F8 W C3 B D6 W E4 B C5 W D4 B B4 W C6 B F4 W F3 B F2 W G4 B E2 W H3 B E3 W G3 B J7 W J4
2013/05/17 03:19:34:457  Received GtpResponse(0x1f37fca0): =  (to GtpCommand(0x1f38a930): gogui-play_sequence W O2 B E5 W D5 B E6 W C4 B F7 W D3 B F8 W C3 B D6 W E4 B C5 W D4 B B4 W C6 B F4 W F3 B F2 W G4 B E2 W H3 B E3 W G3 B J7 W J4)
2013/05/17 03:19:34:457  Command execution succeeded (SyncGTPEngineCommand(0x1f293cf0): name = SyncGTPEngineCommand, undoable = 0)
2013/05/17 03:19:34:457  Executing BackupGameCommand(0x1f256870): name = BackupGameCommand, undoable = 0
2013/05/17 03:19:34:458  BackupGameCommand(0x1f256870): Saving NSCoding archive
2013/05/17 03:19:34:551  Command execution succeeded (BackupGameCommand(0x1f256870): name = BackupGameCommand, undoable = 0)
2013/05/17 03:19:34:552  PlayView, longRunningActionEnds, new value for self.actionsInProgress = 0
2013/05/17 03:19:34:558  Command execution succeeded (ChangeBoardPositionCommand(0x1f24d170): name = ChangeBoardPositionCommand, undoable = 0)
2013/05/17 03:19:34:559  Deallocating BackupGameCommand(0x1f256870): name = BackupGameCommand, undoable = 0
2013/05/17 03:19:34:559  Deallocating SyncGTPEngineCommand(0x1f293cf0): name = SyncGTPEngineCommand, undoable = 0
2013/05/17 03:19:34:559  Deallocating ChangeBoardPositionCommand(0x1f24d170): name = ChangeBoardPositionCommand, undoable = 0
2013/05/17 03:19:34:560  Deallocating DiscardAndPlayCommand(0x1f297300): name = DiscardAndPlayCommand, undoable = 0
2013/05/17 03:19:34:561  Executing BackupGameCommand(0x1f293740): name = BackupGameCommand, undoable = 0
2013/05/17 03:19:34:561  BackupGameCommand(0x1f293740): Saving NSCoding archive
2013/05/17 03:19:34:653  BackupGameCommand(0x1f293740): Saving current game to .sgf file
2013/05/17 03:19:34:653  BackupGameCommand(0x1f293740): Working directory changed to /var/mobile/Applications/EA64E7CA-4482-4705-B905-EE313D60ADD0/Library/Application Support
2013/05/17 03:19:34:653  Submitting GtpCommand(0x1f29d790): savesgf backup.sgf
2013/05/17 03:19:34:659  Received GtpResponse(0x1dd94270): =  (to GtpCommand(0x1f29d790): savesgf backup.sgf)
2013/05/17 03:19:34:660  BackupGameCommand(0x1f293740): Working directory changed to /
2013/05/17 03:19:34:660  Command execution succeeded (BackupGameCommand(0x1f293740): name = BackupGameCommand, undoable = 0)

Here the ComputerPlayMoveCommand is executed that follows the move by black
(PlayMoveCommand).

2013/05/17 03:19:34:660  Executing ComputerPlayMoveCommand(0x1f027d90): name = ComputerPlayMoveCommand, undoable = 0
2013/05/17 03:19:34:660  Submitting GtpCommand(0x1f078020): genmove W
2013/05/17 03:19:34:667  Command execution succeeded (ComputerPlayMoveCommand(0x1f027d90): name = ComputerPlayMoveCommand, undoable = 0)
2013/05/17 03:19:34:667  Deallocating BackupGameCommand(0x1f293740): name = BackupGameCommand, undoable = 0
2013/05/17 03:19:34:668  Deallocating PlayMoveCommand(0x1f073b70): name = PlayMoveCommand, undoable = 0
2013/05/17 03:19:34:676  SymbolsLayerDelegate is drawing
2013/05/17 03:19:34:678  StonesLayerDelegate is drawing
2013/05/17 03:19:35:336  Received GtpResponse(0x1f22baf0): = F5 (to GtpCommand(0x1f078020): genmove W)

Here the GTP engine's response to "genmove" is processed:
ComputerPlayMoveCommand plays the move using GoGame (this is not logged), which
generates a new GoMove and changes the state of the GoPoint object for
intersection F5, and the state of the surrounding GoBoardRegions objects. These
objects now no longer represent the state of the current board position (which
is after "W J4"). From here onwards, Little Go is in a corrupt state!

2013/05/17 03:19:35:350  Executing BackupGameCommand(0x1dd71a70): name = BackupGameCommand, undoable = 0
2013/05/17 03:19:35:350  BackupGameCommand(0x1dd71a70): Saving NSCoding archive
2013/05/17 03:19:35:457  BackupGameCommand(0x1dd71a70): Saving current game to .sgf file
2013/05/17 03:19:35:458  BackupGameCommand(0x1dd71a70): Working directory changed to /var/mobile/Applications/EA64E7CA-4482-4705-B905-EE313D60ADD0/Library/Application Support
2013/05/17 03:19:35:458  Submitting GtpCommand(0x1f24c800): savesgf backup.sgf
2013/05/17 03:19:35:465  Received GtpResponse(0x1f3650f0): =  (to GtpCommand(0x1f24c800): savesgf backup.sgf)
2013/05/17 03:19:35:465  BackupGameCommand(0x1dd71a70): Working directory changed to /
2013/05/17 03:19:35:465  Command execution succeeded (BackupGameCommand(0x1dd71a70): name = BackupGameCommand, undoable = 0)
2013/05/17 03:19:35:474  Deallocating BackupGameCommand(0x1dd71a70): name = BackupGameCommand, undoable = 0
2013/05/17 03:19:35:475  Deallocating ComputerPlayMoveCommand(0x1f027d90): name = ComputerPlayMoveCommand, undoable = 0

Rest of the log file omitted. A lot of things happen until the state
corruption finally becomes noticeable.
@herzbube

This comment has been minimized.

Copy link
Owner Author

commented May 18, 2013

There are two general approaches how to fix the problem:

  • Fix the UI so that the user is prevented from initiating board position changes. This approach is the preferred one, it is also a continuation of the current practice. To succeed we need to identify where the current UI fails. In the first case (iPhone) we have a reproducible case so we can attempt this.
  • Add checks (e.g. to ChangeBoardPositionCommand) to make sure that "rogue" board position changes silently fail. This is not a good approach because it fixes the symptom instead of the original cause. However, if there is no reproducible case we may need to resort to this solution.
@herzbube

This comment has been minimized.

Copy link
Owner Author

commented May 18, 2013

The problem can be reproduced for the iPad using the same steps listed in initial issue description, but there is no plausible explanation yet how the user could inadvertently trigger the board position change, after all the board position navigation buttons are far away from the board where the user is trying to place a stone.

Also, I have not yet succeeded reproducing the problem through tapping a table view cell.

@herzbube

This comment has been minimized.

Copy link
Owner Author

commented May 18, 2013

After a bit of code juggling in PlayMoveCommand and ComputerPlayMoveCommand, everything now runs synchronously from the time when the user lifts the finger to place a stone up to the moment when the GTP command genmove is submitted. Despite this, the problem can still be reproduced:

  • The user lifts the fingertip, causing the UILongPressGestureRecognizer to end the gesture and to trigger placing the stone
  • PlayMoveCommand is executed. The command now runs synchronously in its entirety.
  • ComputerPlayMoveCommand is executed and immediately sets the GoGame property computerThinks to true
  • In reaction, BoardPositionToolbarController disables its buttons
  • Despite the buttons having been disabled, the tap event is still delivered to BoardPositionToolbarController

The conclusion is that iOS receives the tap touch event at a time when the buttons are not yet disabled. iOS then proceeds to first handle the gesture, then as soon as the run loop of the main thread is free it processes the tap touch event.

So it looks as if we have to resort to approach 2 (see comment further up) after all.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.