== Lesson 8: When It Goes Wrong

image::learn/08-when-it-goes-wrong.png[The finished lesson, 480]

You have written a game. From here on you will spend more of your time fixing
programs than writing them, and that is not a sign that anything is wrong with
you. It is the job. The difference between someone who enjoys programming and
someone who gives it up is almost never talent; it is whether they learned to
read what the computer is telling them.

So this lesson has nothing new in it to build. It is the five messages you will
see most often for the rest of your life, what each one actually means, and
four ways of hunting down the mistake behind it. Keep `dodge.singe` from
lesson seven open, because you are going to break it on purpose several times.

=== Two Kinds of Stop

Singe stops for two different reasons, and it says so in two different ways.

When the script will not even start, you get this shape:

----
Error running script:  dodge.singe:92: 'then' expected near 'spawnBlock'
----

Lua reads your whole file before running a word of it, and this means it could
not make sense of what it read. Nothing ran at all.

When the script started fine but something went wrong later, you get this
shape instead:

----
Error executing function 'onOverlayUpdate':  dodge.singe:98: attempt to perform arithmetic on a nil value (global 'blockSped')
stack traceback:
	dodge.singe:98: in function 'updatePlaying'
	dodge.singe:136: in function 'onOverlayUpdate'
----

The game was running. Singe called your `onOverlayUpdate`, as it does sixty
times a second, and this time the call did not come back.

Both shapes contain the same three things, and they are the three things you
want: a file, a line, and a complaint. Read them in that order, every time.

The line numbers in this lesson are from my copy of the file. Yours will be a
line or two out. Nothing about reading an error depends on the number matching.

=== The Ones That Stop It Before It Starts

These are the easy ones, and they are also the ones that feel worst, because
the screen stays black and there is nothing to look at.

Go into `updatePlaying` and delete the word `then` from the line
`if spawnTimer <= 0 then`. Save:

----
Error running script:  dodge.singe:92: 'then' expected near 'spawnBlock'
----

Lua got to the end of the `if` line, wanted the word `then`, and found the
start of the next line instead -- which is `spawnBlock()`, and that is the
`near 'spawnBlock'` part. "Near" means "this is where I noticed", and it is
usually the first thing *after* what you left out.

Now a nastier one. Put `then` back, and instead delete the `end` on the last
line of `spawnBlock`. Save:

----
Error running script:  dodge.singe:148: 'end' expected (to close 'function' at line 58) near <eof>
----

Line 148 is the last line of the file. There is nothing wrong with line 148.
Lua read to the very end -- `<eof>` is what it calls the end of a file -- still
waiting for an `end` that never came, and by then it had swallowed every
function after `spawnBlock` as if it were part of it.

The useful half of that message is `(to close 'function' at line 58)`, which is
where `spawnBlock` begins. When a message points at the end of the file, believe
what it says in the parentheses, not the line number. This is also why the indenting matters so
much: a missing `end` is almost invisible in a list of lines, and obvious the
moment everything below it is indented one step too far.

Two more worth recognising, because you will meet both this week:

----
Error running script:  dodge.singe:41: unfinished string near '"GAME OVER)'
----

A quote you opened and never closed, which you met in lesson one.

----
Error running script:  dodge.singe:135: 'then' expected near '='
----

That one is `if state = "playing" then`. One `=` sets a variable, two `==` ask
a question, and Lua will not let you set one inside an `if`. It looks like a
strange complaint, and it always means the same thing.

=== Attempt to Index a Nil Value

This is the one you will see most, by a wide margin.

Go into `spawnBlock` and misspell `block` on the first line that uses it, so
it reads `blocl.x = math.random(0, screenWidth - BLOCK_SIZE)`. Save, press
space:

----
Error executing function 'onOverlayUpdate':  dodge.singe:60: attempt to index a nil value (global 'blocl')
stack traceback:
	dodge.singe:60: in function 'spawnBlock'
	dodge.singe:92: in function 'updatePlaying'
	dodge.singe:136: in function 'onOverlayUpdate'
----

*Indexing* is what the dot does. `blocl.x` means "go into the thing called
`blocl` and find the `x` in it". You can only do that to a table.

*Nil* is what Lua calls a name with nothing behind it. You have not seen much
of it because you have been careful to give everything a value, but every name
you have never used is `nil` already, and typing a name wrong invents a brand
new one.

So the whole message says: *you used a dot on something that does not exist*.

The part in parentheses is the gift. `global 'blocl'` is the exact name of the
thing that was empty. Search your file for it. If it appears exactly once, it
is a spelling mistake, and you have found it in ten seconds.

The word before the name tells you where Lua looked for it:

* `global` -- a name with no `local` in front of it anywhere.
* `local` -- a name you declared with `local` in the function you are in.
* `field` -- a name after a dot, like the `y` in `block.y`.
* `upvalue` -- a `local` from further out that this function can see, which
  is what all of `dodge.singe`'s variables are, since they are declared at the
  top of the file and used inside functions.

`field` is the other common cause, and it is not a spelling mistake at all. If
you wrote `block.hit.when` and never set `block.hit`, you get
`attempt to index a nil value (field 'hit')`. The dot that fails is the second
one. Lua tells you which by naming it.

=== Attempt to Call a Nil Value

Put `blocl` back. Now misspell an engine function: in `drawGame`, change
`overlayPrint` to `overlayPirnt`. Save:

----
Error executing function 'onOverlayUpdate':  dodge.singe:36: attempt to call a nil value (global 'overlayPirnt')
stack traceback:
	dodge.singe:36: in function 'drawGame'
	dodge.singe:140: in function 'onOverlayUpdate'
----

Same `nil`, different crime. *Calling* is what the parentheses do, and you can
only do that to a function. There is no function called `overlayPirnt`, so
`overlayPirnt` is `nil`, so the parentheses have nothing to call.

This happens for four reasons, in order of how often:

. You misspelled one of your own functions.
. You misspelled one of Singe's. Nothing in the engine checks your spelling
  when the file loads, so a misspelled engine name is just another name that
  happens to be empty, and it costs you nothing until the line runs.
. The function does not exist in Singe at all -- it was a reasonable guess, and
  reasonable guesses are wrong about half the time. The manual's function list
  is the only way to be sure.
. You made it `local` and called it from somewhere above where it is declared.
  This is exactly why the functions in `dodge.singe` are global.

There is a much worse version of this mistake, and you met it in lesson one
without knowing: spell a *callback* wrong and you get no message at all.
`onOverlayUpdated` is not an error. It is a perfectly good function that Singe
has never heard of and will never call, so the screen stays black and nothing
complains. When a whole feature does nothing whatsoever, suspect the name.

=== Attempt to Perform Arithmetic on a Nil Value

Put `overlayPrint` back. In `updatePlaying`, misspell `blockSpeed` in the
falling line, so it reads `block.y = block.y + blockSped`:

----
Error executing function 'onOverlayUpdate':  dodge.singe:98: attempt to perform arithmetic on a nil value (global 'blockSped')
stack traceback:
	dodge.singe:98: in function 'updatePlaying'
	dodge.singe:136: in function 'onOverlayUpdate'
----

Arithmetic is `+`, `-`, `*`, and `/`. You cannot add nothing to a number.
Again the parentheses name the empty thing, and again the commonest cause is a
typo -- but this one has a second cause that is worth knowing, because it is
harder to see.

A variable you never gave a number to is `nil`, not zero. If you add a high
score to the game and write `local hiScore` at the top without `= 0`, it holds
`nil` until something sets it, and the first `hiScore + score` stops the game.
Lua does not start numbers at zero for you. You start them at zero.

Two close relatives, with the same cause and the same cure:

----
dodge.singe:37: attempt to concatenate a nil value (upvalue 'hiScore')
----

`..` joining a string to something that is not there. You will see this one
whenever you print a score you forgot to set.

----
dodge.singe:118: attempt to compare number with nil
----

That is `if lives > 0 then` with nothing in `lives`. Note that this message
does not name anything in parentheses. When Lua cannot tell you which side was
empty, the next section is how you find out.

=== An Argument of the Wrong Kind

Every message so far came from Lua. This one comes from Singe, and it looks
completely different, so it is worth meeting on purpose.

Suppose you want to see what is in `blocks`, and you try to print it. Add this
line to `drawGame`, under the score:

[source,lua]
----
    overlayPrint(1, 3, blocks)
----

----
37:overlayPrint:  Argument 3 must be a string.
----

No file name, no traceback, no `attempt to` anything. An engine complaint
starts with the line number, then the name of the function that refused, then
what it wanted. Here `overlayPrint` was handed a table where it needs text, and
it stopped rather than draw something meaningless.

The sibling message counts rather than checks:

----
34:overlayBox:  Expected 4 argument(s), got 3.
----

That is an `overlayBox` with a corner missing. The odd-looking `argument(s)` is
the engine's, not a typo of yours.

When you get one of these, the manual's entry for that function is the answer,
and it will take you a minute. Every entry lists the arguments in order with
what each one has to be. Singe checks them because the alternative is a game
that runs for ten minutes and then draws garbage.

=== Finding Out What Is Really in There

Half of debugging is not reading errors at all. It is the case where nothing
crashes and nothing works: blocks that never appear, a player who will not
move, a score stuck at zero. For that you need to see inside the running game,
and there are two ways.

The first is `debugPrint`, which writes a line to the terminal you started
Singe from. Take the line you cannot make sense of and put one above it:

[source,lua]
----
    debugPrint("blocks " .. #blocks .. ", timer " .. spawnTimer)
----

Now you are looking at what is actually there instead of what you are sure is
there, and that gap is where bugs live. Run it and you will see the truth
about `playerX`, too: it prints as `160.0`, not `160`, because dividing with
`/` in Lua always gives a number with a fractional part, even when the
fraction is zero.

Two things will bite you. The first is that `debugPrint` insists on text or a
number; hand it anything else and it stops the game the way `overlayPrint`
did. `debugPrint(blocks)` will not show you a list, and
`debugPrint("left " .. goingLeft)` will not show you a `true` or a `false`
either:

----
dodge.singe:78: attempt to concatenate a boolean value (upvalue 'goingLeft')
----

`tostring` is the fix. It takes anything at all and gives you text for it, so
`tostring(goingLeft)` is `"true"` or `"false"` and the line works.

The second is that `onOverlayUpdate` runs sixty times a second, so a
`debugPrint` inside it prints sixty lines a second and you cannot read any of
them. The manual says as much in its entry: the call is cheap, but nothing
throttles it.

Before anything else, put one switch in front of every debug line you add, so
that you can turn the noise off without hunting them down again:

[source,lua]
----
local DEBUG = true


function debugLog(text)
    if DEBUG then
        debugPrint(text)
    end
end
----

Every `debugLog` in the game obeys that one `true`. Change it to `false` and
the game goes quiet; change it back and everything returns.

Then print when something *happens* rather than every frame:

[source,lua]
----
            debugLog("hit at y " .. math.floor(block.y) .. ", lives now " .. lives)
----

Or print on a timer, counted down exactly the way blocks are spawned:

[source,lua]
----
    reportTimer = reportTimer - 1
    if reportTimer <= 0 then
        debugReport()
        reportTimer = REPORT_FRAMES
    end
----

The `learn` folder has the whole thing as `08-when-it-goes-wrong.singe`: it is
lesson seven's game with a report about every two seconds, a line when you get
hit, and a line when the game ends.

The second way to see inside is to put it on screen, which is better for
anything that changes every frame, because sixty lines a second in a terminal
is useless but a number that ticks in the corner is easy to watch:

[source,lua]
----
    if DEBUG then
        overlayPrint(1, 3, "BLOCKS " .. #blocks .. "   PLAYER " .. playerX)
    end
----

=== Cutting the Problem in Half

When you cannot see which of twenty lines is wrong, stop looking and start
removing.

Put two dashes at the start of a line and Lua ignores the rest of it. That is
a *comment*, and the usual use is to leave notes for yourself, but the better
use is this one:

[source,lua]
----
    -- overlayPrint(1, 1, "SCORE " .. score .. "    LIVES " .. lives)
----

Comment out half of `drawGame` and run it. If the problem is still there, it
is in the half you kept. If it went away, it is in the half you removed. Put
that half back and cut *it* in half. Twenty lines takes five rounds of this,
and each round is one save and one look.

It works on more than lines. Comment out the body of `updatePlaying` and the
blocks stop moving, which tells you whether the thing you are chasing is in
the moving or in the drawing. Comment out the `collideRects` branch and see
whether the game stops crashing. You are not trying to fix anything while you
do this. You are trying to find out where it is not.

=== Going Round Faster

All of this depends on being able to try something in a couple of seconds, and
that is what `-R` is for. You have been using it since lesson one; here is what
it is actually doing, and it is worth knowing now that you are going to lean on
it.

Singe watches every script file your game loaded. When you save one, the game
starts again from the beginning: everything the script made is thrown away and
your file is run afresh, in the time it takes to read the file rather than the
time it takes to start the engine. `F5` does the same on demand, without
saving anything.

A key you are holding through a reload is ignored until you let go, so the
player will not run off on his own after a reload.

The two kinds of stop behave differently here, and it is useful to know which
you are looking at without reading the message. A script that will not compile
is *printed and survived*: the window stays open and empty, the file stays
watched, and saving the fix brings the game back. A crash inside a callback --
all the `attempt to` messages, and the engine's argument complaints -- takes
Singe down, and you start it again by hand.

=== Reading a Traceback

The lines under `stack traceback:` are the list of functions that were in
progress when everything stopped, innermost first. Here is the one from
`blocl` again:

----
	dodge.singe:60: in function 'spawnBlock'
	dodge.singe:92: in function 'updatePlaying'
	dodge.singe:136: in function 'onOverlayUpdate'
----

Read it from the bottom up and it is a sentence. Singe called
`onOverlayUpdate`. At line 136, `onOverlayUpdate` called `updatePlaying`. At
line 92, `updatePlaying` called `spawnBlock`. At line 60, `spawnBlock` gave up.

The top line is where it broke. The lines under it are how it got there, and
they are what you need when the top line looks innocent. A function that adds
a number to `block.y` is not wrong; a function that put a block in the list
without a `y` is. Only the trail joins the two, and the trail is printed for
you every single time.

=== The Habit

Everything above is technique. This is the habit, and it matters more:

*Change one thing. Run it. Look at what happened.*

When something will not work, the temptation is to change four things at once,
because one of them is bound to be it. Do that and it stops working in a new
way, and now you do not know which of the four did it, or whether two of them
are cancelling out. You have made the problem bigger and hidden it better.

One change. Run. Look. It feels slower. It is the fastest thing there is, and
every experienced programmer you will ever meet does it, for exactly the
reason you are about to find out.

=== Try It

. *Meet them all.* Make each of the five mistakes in this lesson in
  `dodge.singe` on purpose, one at a time, and read the message before you fix
  it. You will never be afraid of them again.
. *Watch the spawner.* Put a `debugPrint` inside `spawnBlock` that prints the
  new block's `x`. Play for thirty seconds, then look at the numbers. Are they
  spread across the screen, or do they favour one end?
. *Turn it off.* Change `DEBUG` to `false` in the lesson script, and satisfy
  yourself that nothing prints and the game is unchanged.
. *A bug with no error.* Change the falling loop to run forwards, so it reads
  `for i = 1, #blocks do`. Play a round. Nothing crashes and nothing is
  printed, but the game is wrong. Put a `debugPrint` inside that loop and work
  out what it is really doing.
. *Break a callback's name.* Rename `onInputPressed` to `onInputPress` and run
  it. Nothing is printed, nothing crashes, the player will not move, and space
  will not start a game. Then explain to yourself why that is the most
  dangerous mistake in this lesson.

=== What You Learned

* Errors have a file, a line, and a complaint. Read them in that order.
* `Error running script` means nothing ran; the shape with a traceback means it
  was running and stopped.
* `nil` is a name with nothing behind it, and it is behind most error messages
  you will ever see.
* The word in parentheses names the empty thing, and says whether it was a
  global, a local, a field, or an upvalue.
* A missing `end` is reported at the end of the file, and the parentheses tell
  you where the mistake really is.
* Engine complaints look different: a line number, a function name, and what it
  wanted instead.
* `debugPrint` shows you what a variable really holds. `tostring` makes
  anything printable, and a switch like `DEBUG` turns the noise off.
* Comment a half out with `--` to find out which half the problem is in.
* A misspelled callback produces no error at all, which makes it worse than one
  that does.
* Change one thing, run it, look.

=== Next Time

That is the end of part one. You can write a game, and now you can fix one,
which means everything from here is addition rather than foundation. Part two
starts by replacing those coloured boxes with actual pictures, and from there
the game you have been building begins to look like a game somebody else
would want to play.