Include scanning cache broken for non-arduino boards

[majenkotech]

First compilation works perfectly. Second compilation crashes arduino-builder:

panic: runtime error: index out of range

goroutine 1 [running]:
panic(0x556bc0, 0xc420018130)
	/home/jenkins/go/src/runtime/panic.go:500 +0x1a1
arduino.cc/builder.findIncludesUntilDone(0xc420060400, 0xc4202f5d40, 0x556f40, 0xc4201f90e0, 0xc420381162, 0x18, 0x0, 0x0)
	/home/jenkins/workspace/arduino-builder-all-cross/src/arduino.cc/builder/container_find_includes.go:321 +0x138f
arduino.cc/builder.(*ContainerFindIncludes).Run(0x64d248, 0xc420060400, 0x41bc3c3c, 0x0)
	/home/jenkins/workspace/arduino-builder-all-cross/src/arduino.cc/builder/container_find_includes.go:149 +0x5e4
arduino.cc/builder.runCommands(0xc420060400, 0xc42019fad8, 0x22, 0x22, 0x1, 0x0, 0x0)
	/home/jenkins/workspace/arduino-builder-all-cross/src/arduino.cc/builder/builder.go:191 +0xcd
arduino.cc/builder.(*Builder).Run(0xc42019fd28, 0xc420060400, 0xc420045d88, 0x562240)
	/home/jenkins/workspace/arduino-builder-all-cross/src/arduino.cc/builder/builder.go:124 +0xb9c
arduino.cc/builder.RunBuilder(0xc420060400, 0xc420045d88, 0x64d248)
	/home/jenkins/workspace/arduino-builder-all-cross/src/arduino.cc/builder/builder.go:222 +0x35
main.main()
	/home/jenkins/workspace/arduino-builder-all-cross/src/arduino.cc/arduino-builder/main.go:338 +0x99c
/home/matt/Downloads/arduino-1.8.2/arduino-builder returned 2

Environment

Core URL: https://raw.githubusercontent.com/chipKIT32/chipKIT-core/master/package_chipkit_index.json
Test board: chipKIT MAX32
Operating System: Linux (64 bit)
IDE version: 1.8.2

Steps to reproduce

1. Install the required boards package and select the right board
2. Install the required library (below)
3. Paste in the test sketch and compile (succeeds)
4. Compile again - fails.

Test Sketch

Required library: https://www.dimensionengineering.com/software/SabertoothArduinoLibraries.zip (though any contributed library may do it)

// playing with motor driver
#include <SabertoothSimplified.h>

#define MAIN_LED_PIN 13

SabertoothSimplified ST( Serial1 );
                                        
void setup()
{
  pinMode( MAIN_LED_PIN, OUTPUT );

  //SabertoothTXPinSerial.begin(38400);
  Serial1.begin( 38400 );
}

void loop()
{
  ST.motor(1, 127);  // Go forward at full power.
  ST.motor(2, 127);
  delay( 2000 );       // Wait 2 seconds.
  ST.motor(1, 0);    // Stop.
  ST.motor(2, 50);
  delay(2000);       // Wait 2 seconds.
  ST.motor(1, -127); // Reverse at full power.
  ST.motor(2, -80 );
  delay(2000);       // Wait 2 seconds.
  ST.motor(1, 0);    // Stop.
  ST.motor(2, -127 );
  delay(2000);
  ST.motor( 2, 0 );
  delay( 1000 );

  // do heartbeat blink
  digitalWrite( MAIN_LED_PIN, HIGH );
  delay( 500 );
  digitalWrite( MAIN_LED_PIN, LOW );
  delay( 500 );
}

[matthijskooijman]

The error points here: https://github.com/arduino/arduino-builder/blob/1.3.25/src/arduino.cc/builder/container_find_includes.go#L321
Given there is no index there, I think Next() got inlined: https://github.com/arduino/arduino-builder/blob/1.3.25/src/arduino.cc/builder/container_find_includes.go#L209

Looking at the code, I suspect that cache.valid is true, but cache.next points past the end of the cache. The comments suggest that ExpectFile should make cache.valid in this case, but it doesn't seem to, so that's probably the cause here.

If this is indeed correct, then this bug is not triggered by a third-party board, but by adding a file between two compilations, and only if this file is named such that it is compiled last. @majenkotech, does this sound familiar? Did this bug trigger just once, or could you repeatedly reproduce it?

I quickly tried to reproduce the problem using my analysis, which didn't work so far. I'll have a closer look and submit a PR to at least fix the problem I noticed.

[majenkotech]

It's reproducible every time. It's something we have been experiencing since IDE 1.6.12. At the time I tracked it down to something that changed between IDE 1.6.11 and 1.6.12, which included an upgrade to arduino-builder 1.3.21.

I never went any further than that in my digging, since I'm not a user of the Arduino IDE. Our advice to people 'till now has been "Use Arduino 1.6.11 or UECIDE"

Nothing gets added or changed between compilations. Just press the compile button once, then, when compilation is finished, press it again.

[matthijskooijman]

Interesting, then there might be something else going on than I thought. arduino-builder 1.3.21 introduced caching for include detection, which is clearly where this problem originates. I'll see if I can reproduce this based on your instructions (thanks for the complete an elaborate report, btw!)

[majenkotech]

You're welcome ;) Being a developer myself I know what I like to know to reproduce a bug ;)

[matthijskooijman]

I can reproduce this, it indeed seems related to the board, not the sketch (any sketch that includes a library or has an additional .cpp file seems to trigger this). Somehow the cache doesn't get filled properly, and the bug I previously spotted turns this into a crash. I'm out of time for today, but I'll have a closer look next week or the week after.

[majenkotech]

Certainly deleting the includes.cache makes it compile a second time.

Comparing the includes.cache file when compiled for the Arduino Uno and when compiled for the chipKIT MAX32 does yield some interesting differences.

This is when compiled for the Uno:

[
  {
    "Sourcefile": "",
    "Include": "",
    "Includepath": "/home/matt/Downloads/arduino-1.8.2/hardware/arduino/avr/cores/arduino"
  },
  {
    "Sourcefile": "",
    "Include": "",
    "Includepath": "/home/matt/Downloads/arduino-1.8.2/hardware/arduino/avr/variants/standard"
  },
  {
    "Sourcefile": "/tmp/arduino_build_708154/sketch/sketch_jun02a.ino.cpp",
    "Include": "SabertoothSimplified.h",
    "Includepath": "/home/matt/Arduino/libraries/SabertoothSimplified"
  },
  {
    "Sourcefile": "/tmp/arduino_build_708154/sketch/sketch_jun02a.ino.cpp",
    "Include": "",
    "Includepath": ""
  },
  {
    "Sourcefile": "/home/matt/Arduino/libraries/SabertoothSimplified/SabertoothSimplified.cpp",
    "Include": "",
    "Includepath": ""
  }
]

And this for the Max32:

[
  {
    "Sourcefile": "",
    "Include": "",
    "Includepath": "/home/matt/.arduino15/packages/chipKIT/hardware/pic32/1.4.1/cores/pic32"
  },
  {
    "Sourcefile": "",
    "Include": "",
    "Includepath": "/home/matt/.arduino15/packages/chipKIT/hardware/pic32/1.4.1/variants/Max32"
  },
  {
    "Sourcefile": "/tmp/arduino_build_708154/sketch/sketch_jun02a.ino.cpp",
    "Include": "SabertoothSimplified.h",
    "Includepath": "/home/matt/Arduino/libraries/SabertoothSimplified"
  }
]

There's no SabretoothSimplified.cpp entry in the Max32, and the Uno has two sketch_jun02a.ino.cpp entries whereas the Max32 only has the one.

Basically the last two entries are missing...

So certainly it's not filling the file in right (or in the same way) for the Max32 (or any chipKIT board for that matter).

[matthijskooijman]

Your observations match mine. Looking more closely, here's what happens:

1. The include detection runs a file through the preprocessor. The commandline and output looks like this (a lot of options not shown):
   $ "pic32-g++" -c -g -O2 -w -MMD -fno-exceptions -w -x c++ -E -CC "foo.cpp" -o "/dev/null"
   :0:0: fatal error: opening dependency file /dev/null.d: Permission denied
   compilation terminated.

2. The include detection notes that compilation failed, but cannot find a #include error message to resolve to a library. To show the error message to the user, the gcc command is run again, but without capturing stderr:
   "pic32-g++" -c -g -O2 -w -MMD -fno-exceptions -w -x c++ -E -CC "foo.cpp" -o "/tmp/arduino_build_static/preproc/ctags_target_for_gcc_minus_e.cpp"

   However, the target filename is also different, preventing the error from occuring. Without this error, compilation continues, even though no meaningful include detection has happend.

Looking at the Arduino Uno command, there is no -MMD option in the commandline, which prevents this problem.

There's a few things wrong here:

• The command fails due to the /dev/null.d thing. This is the actual problem.
• The command is run twice with different arguments, preventing the error from being shown as expected.
• The include cache has a bug that makes it crash when the include cache file is incomplete.

The latter two are easy to fix, the first one needs a bit of thought. The preprocessor recipes are a bit of a mess, since they were originally used in a different way than they are now I believe, so there's a bit of legacy involved (and no clear definition of what a recipe is expected to do). The primary problem here is that -MMD is not relevant here, and does not combine well with -o /dev/null.

Looking more closely at the code, it seems that there is already handling to remove -MMD from the commandline: https://github.com/arduino/arduino-builder/blob/master/src/arduino.cc/builder/gcc_preproc_runner.go#L119

However, that code removes the flag specifically from the compiler.cpp.flags entry. Chipkit has the -MMD flag in the compiler.c.flags entry, which is again included by the compiler.cpp.flags entry (but this inclusion happens later in the process, I assume). Fixing this requires to apply the "remove -MMD"-feature to be applied after the interpolation of the command, but that happens in the more generic ExecRecipe() / PrepareCommandForRecipe(). So that probably requires passing a flag to apply this extra processing, or perhaps more generically passing a function pointer of a post-processing step to apply.

To work around this problem on the chipkit side, chipkit's platform.txt could be changed to not include compiler.c.flags from compiler.cpp.flags and instead duplicate the options, like the Arduino version does. This should fix compatibility with all previous versions, while the fix on the arduino-builder side can only work for newer versions (but needs to happen anyway).

[majenkotech]

Brilliant. That's an easy fix then. We can roll a new chipkit-core version to get a fix out without waiting for an arduino-builder-based fix to make its way into a new IDE version. That's what I like to hear.