Include scanning cache broken for non-arduino boards #230

majenkotech · 2017-06-02T09:34:39Z

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

Install the required boards package and select the right board
Install the required library (below)
Paste in the test sketch and compile (succeeds)
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 );
}

The text was updated successfully, but these errors were encountered:

matthijskooijman · 2017-06-02T15:56:58Z

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 · 2017-06-02T16:02:15Z

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 · 2017-06-02T16:08:06Z

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 · 2017-06-02T16:08:58Z

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

matthijskooijman · 2017-06-02T20:24:03Z

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 · 2017-06-02T21:16:33Z

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 · 2017-06-06T09:37:24Z

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

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.
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 · 2017-06-06T11:46:48Z

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.

The comments state that if ExpectFile() is called, but there are no remaining items in the cache, it will invalidate the cache. However, the code would only invalidate the cache if at least one item was still present, but it didn't match the expected file. In practice, this wouldn't usually cause issues, since adding a new file would usually cause an invalid cache earlier on, and even if a new file was added at the end of the compilation, it would not be in the .d file, so it would be marked as "changed". However, in rare circumstances, such as when the include cache would not be properly generated due to other problems (see arduino#230), this would cause a crash, when ExpectFile did not invalidate the cache and the file in question was unchanged, causing an out-of-bounds read from the cache. This commit fixes this by making ExpectFile behave like documented and invalidate the cache when there are no remaining entries. Signed-off-by: Matthijs Kooijman <matthijs@stdin.nl>

For include detection, the preprocessor is run on all source files, collecting #included filenames from the stderr output, each of which are then resolved to a library to include. A caching mechanism is used to only run the preprocessor when needed. This commit improves the error handling during include detection in a number of ways: - When the preprocessor runs succesfully, processing stops for the current file. Previously, it would always look at stderr to find a missing include filename and only stop if none was found. - When the preprocessor fails, but no filename can be found, show the error preprocessor error. Previously, it would assume that the process was done and stop processing the file without any error. - When no library can be found for a missing include, show the stored error output instead of running the preprocessor again. Previously, the preprocessor would be run a second time, to (re)generate the error message. When the include filename comes from the cache and the preprocessor was not run yet, it is still run to show its errors to the user. This should be very rare, as normally changes that cause a cached filename to become unresolvable to a library also cause the file to be marked as changed, bypassing the cache. When this does happen, the preprocessor is now run using `GCCPreprocRunnerForDiscoveringIncludes()` instead of `GCCPreprocRunner()`, which ensures the preprocessor command is always exactly the same. Before this change, there could be specific circumstances where the first preprocessor run would generate an error, but where the second run would not show the error and include detection would continue as if nothing happened. One such circumstance is described in arduino#230. Signed-off-by: Matthijs Kooijman <matthijs@stdin.nl>

Usually, the `preproc.macros` recipe includes the C/C++ flags, and through that the `-MMD` flag to generate dependency files. However, since include detection passed an output file of `/dev/null` (or the equivalent on other operating systems), this causes gcc to try and generate a `/dev/null.d` file and fail. To prevent this, the `-MMD` flag was filtered out, but this filtering was applied to the `compiler.cpp.flags` variable, where it *usually* comes from. However, this is not necessarily true for all platforms. For example, the PIC32 platform used to have this flag in the `compiler.c.flags` variable and have `compiler.cpp.flags` include that. This prevented the flag from being filtered away and caused a failure. Due to previous changes, it is now possible for this filtering to happen after all variables have been replaced and the command to run was generated, but before actually running it. An extra advantage is that the filtering is more robust than the previous substring-based filtering. This fixes arduino#230. Signed-off-by: Matthijs Kooijman <matthijs@stdin.nl>