Blair Conrad

Automatically Sync nupkg and project.json Dependencies

Tue, 21 Feb 2017 00:00:00 +0000

Recently while working on an open source .NET project, I forgot to update the .nuspec after changing a package dependency in my project.json. Of course the resulting nupkg contained the wrong dependency. Fortunately, the package wasn't published in that state, but I didn't want to risk such a thing happening again.

I want the project to be buildable in Visual Studio immediately after cloning, but there's no such constraint on producing the NuGet package, so this means the project.json has to be the source of truth.

I opted to have the project's simple-targets-csx build script scrape the project.json for the version of the dependent package and supply the matching version as part of the nuget pack properties option.

My initial implementation used a regular expression to extract the version, but my colleague Thomas Levesque suggested parsing the JSON to find the proper value.

I liked the idea, but pulling in something like Json.NET seemd heavy. A little Googling later, I found Brandur Leach's Using the Little-known Built-in .NET JSON Parser that described the built-in JsonReaderWriterFactory. This seemed like just the ticket. A few minutes later, I was up and running with these sections of the build script

targets.Add(
    "pack",
    DependsOn("build", "outputDirectory"),
    () =>
    {
        var fakeItEasyVersion = GetDependencyVersion("FakeItEasy");
        Cmd(nuget, $"pack {nuspec} -Version {version} -Properties FakeItEasyVersion={fakeItEasyVersion} -OutputDirectory {outputDirectory} -NoPackageAnalysis");
    });

…

public string GetDependencyVersion(string packageName)
{
    byte[] buffer = File.ReadAllBytes(projectJsonPath);
    XmlReader reader = JsonReaderWriterFactory.CreateJsonReader(buffer, new XmlDictionaryReaderQuotas());

    XElement root = XElement.Load(reader);
    return root.Element("dependencies").Element(packageName).Value;
}

which find the "3.0.0-rc001-build000097" from the project.json:

{
  "dependencies": {
    "FakeItEasy": "3.0.0-rc001-build000097",
    "StyleCop.Analyzers": "1.1.0-beta001"
  },
  …

and combine it with this portion of the .nuspec:

<dependencies>
  <dependency id="FakeItEasy" version="[$FakeItEasyVersion$,4)" />
</dependencies>

Of course, a property could be added for each dependency. Do this, and you can rest easy, knowing you'll never get a dependency mismatch again.

Select May Not be Broken, But it's Bent

Mon, 05 Oct 2015 00:00:00 +0000

Earlier this week at the day job I ran into an interesting problem working with a DataTable. A view that's supposed to show a subset of the table's rows showed nothing. I dropped into the debugger and became even more confused.

Visually inspecting the DataTable showed that there was a row that matched the filter the view was using, but running Select still returned nothing. I didn't bring work's code home, but here's some code that reproduces the problem:

Console.Out.WriteLine("0th book's Library:\t{0}", books[0].Library);
Console.Out.WriteLine("# WPL books by Select:\t{0}", library.Books.Select("Library = 'WPL'").Length);
Console.Out.WriteLine("# WPL books by LINQ:\t{0}", library.Books.Count(book => book.Library == "WPL"));

And the output:

0th book's Library:     WPL
# WPL books by Select:  0
# WPL books by LINQ:    1

So, the table contains at least one book from WPL, Selecting for that library doesn't find the book, yet iterating over all the rows and Counting them does find it.

Just in case you think there's some whitespace trickery going on or something, debug with me:

How is this happening? The row's Library property is actually DBNull, but the dataset defines both DefaultValue and NullValue:

So even though there was DBNull in the row, whenever I examined the Library property, via code (such as the LINQ statements) or visually in the debugger, it appeared to be "WPL".

Select, however, wasn't fooled. It knew the value was DBNull and wouldn't match.

I'm of two minds about this. It's arguably correct behaviour, as the stored value is not "WPL", but I'm not sure that it's desirable to be able to configure the table to present data in a way that's not supported by the query.

App Engine + External Authentication: Exposing Handlers to Cron, Tasks, and Admins

Mon, 05 Jan 2015 00:00:00 +0000

Since Google is deprecating OpenID 2.0 support, I decided to update LibraryHippo to authenticate via OAuth 2.0, which is a story in itself, but I'm here to talk about what happened next.

LibraryHippo has a set of handlers that are accessed primarily via the Cron and Task Queue mechanisms, but every once in a while need to be triggered ad hoc by a human administrator. Up 'til now, these request handlers were protected from the rabble by requiring administrator status via the application's app.yaml. Unfortunately, externally-authenticated users have no special standing within App Engine, so this restriction had to be relaxed.

My first thought was to remove the restriction from app.yaml and check for access in the handler like so:

if (users.is_current_user_admin() or
    self.is_external_user_admin()) # application code that understands the logged-in users
    # do stuff
else:
    self.abort(403)

Unfortunately, this fails miserably. When the handler is executed by a task or cron job, users.is_current_user_admin returns False.

This behaviour seems not to be widely reported; I couldn't find it mentioned in the App Engine issues list, but a web search eventually turned up App Engine: Google fails users.is_current_user_admin() test by Ben Davies, an article written nearly 5 years ago.

In this article, Mr. Davies suggests that the best alternative to users.is_current_user_admin is to "check the easily spoofed request user-agent". I was skittish of this approach, especially since Google is now recommending checking X-AppEngine-Cron when securing URLS for cron. The App Engine documentation explains how X-AppEngine-Cron is protected against spoofing, but I'm still uneasy.

I ended up taking a different approach. I added two routes for the affected handlers. One route is in the old "admin" subdirectory (subpath?) and the other in a new one for system commands, "system". The latter is secured in the app.yaml, just as before. Thus I have:

# in app.yaml
- url: /system/.*
  script: libraryhippo.application
  login: admin

# in the application's Python source
handlers = [
    # other handlers
    ('/admin/notify/(.*)$', Notify),
    ('/system/notify/(.*)$', Notify),
    ]

# and later, in the Notify handler
    request_path = urlparse.urlsplit(self.request.url).path
    if (self.is_external_user_admin() or
        not request_path.startswith('/admin/'))
        # do stuff
    else:
        self.abort(403)

Thus the handler is executed if the user has admin rights or the URL isn't locked down by virtue of being below '/admin/'. The '/system/' URLs are all assumed to be protected by the app.yaml setting.

Perhaps this is technically no better than checking a header in the request, but it works for me, at least until I see what happens with Issue 11576: have users.is_current_user_admin return true for tasks and cron jobs.

Hasty Impressions: flake8

Mon, 15 Sep 2014 00:00:00 +0000

A little while ago, I was fixing a LibraryHippo issue in an area of the code that didn't have very good unit test coverage. As part of my fix, I moved one class from the main libraryhippo.py file to its own file. I integration-tested the fix, deployed the new version, and moved on.

A day or so later, I noticed that I'd broken a very important side effect of the card-checking operation. The results of the check are cached and used later when sending out notifications. Because we still want to deliver a live report to users even if the caching fails, the failure is not detectable from the web page.

Of course better test coverage would've picked this up, but it's the sort of error that just as easily would've been caught in a compiled language such as C#, or by a static analysis tool. So I decided to try out such a tool.

A few web searches later, and it looked like flake8 was the thing to try. It bundles together

None of which I'd heard of before, (at least as packages—I'd known of PEP 8 for a long time), but they claimed to do what I wanted. So I gave flake8 a go.

Initial impressions

Installation was as easy as running pip install flake8. It picked up the missing dependencies automatically, and I was ready to go in seconds.

Too impatient to read any docs, I ran it:

LibraryHippo> flake8
Usage: flake8 [options] input ...
flake8: error: input not specified

A helpful error message. I reran, specifying the application directory (flake8 App) and got… rather a lot of output. It looked like this:

app\BeautifulSoup.py:100:1: E265 block comment should start with '# '
app\BeautifulSoup.py:107:1: E302 expected 2 blank lines, found 1
app\BeautifulSoup.py:114:1: E302 expected 2 blank lines, found 1
⋮
app\cardchecker.py:61:13: F841 local variable 'name' is assigned to but never used
app\cardchecker.py:63:80: E501 line too long (96 > 79 characters)
app\cardchecker.py:71:37: F821 undefined name 'clock'
app\cardchecker.py:74:80: E501 line too long (84 > 79 characters)
app\cardchecker.py:75:1: W391 blank line at end of file
⋮

and so on. Success!

Too many complaints!

Things seemed to be working, and it did identify the cause of my error (app\cardchecker.py:71:37: F821 undefined name 'clock'), but it was buried in way too much other information.

flake8 reported 823 problems in my application (and that didn't even include the test code). This is a common problem when running any kind of analysis tool for the first time. Since we've not been running a tight ship, there are all kinds of problems in the code. Fortunately, like many tools of its ilk, flake8 lets us tailor the problems that are reported. I had two immediate goals:

ignore complaints about the library BeautifulSoup (over half the complaints were from BeautifulSoup.py), and
ignore (for now) less severe errors and style warnings

Now, how to do that?

Command-line help

I hoped that the tool would give me useful help if I asked, and it did:

LibraryHippo>flake8  -h
Usage: flake8 [options] input ...

Options:
  --version             show program's version number and exit
  -h, --help            show this help message and exit
  -v, --verbose         print status messages, or debug with -vv
  -q, --quiet           report only file names, or nothing with -qq
  --first               show first occurrence of each error
  --exclude=patterns    exclude files or directories which match these comma
                        separated patterns (default:
                        .svn,CVS,.bzr,.hg,.git,__pycache__)
  --filename=patterns   when parsing directories, only check filenames
                        matching these comma separated patterns (default:
                        *.py)
  --select=errors       select errors and warnings (e.g. E,W6)
  --ignore=errors       skip errors and warnings (e.g. E4,W)
  --show-source         show source code for each error
  --show-pep8           show text of PEP 8 for each error (implies --first)
  --statistics          count errors and warnings
  --count               print total number of errors and warnings to standard
                        error and set exit code to 1 if total is not null
  --max-line-length=n   set maximum allowed line length (default: 79)
  --hang-closing        hang closing bracket instead of matching indentation
                        of opening bracket's line
  --format=format       set the error format [default|pylint|<custom>]
  --diff                report only lines changed according to the unified
                        diff received on STDIN
  -j JOBS, --jobs=JOBS  number of jobs to run simultaneously, or 'auto'
  --exit-zero           exit with code 0 even if there are errors
  --builtins=BUILTINS   define more built-ins, comma separated
  --doctests            check syntax of the doctests
  --max-complexity=MAX_COMPLEXITY
                        McCabe complexity threshold
  --install-hook        Install the appropriate hook for this repository.

  Testing Options:
    --benchmark         measure processing speed

  Configuration:
    The project options are read from the [flake8] section of the tox.ini
    file or the setup.cfg file located in any parent folder of the path(s)
    being processed.  Allowed options are: exclude, filename, select,
    ignore, max-line-length, hang-closing, count, format, quiet, show-
    pep8, show-source, statistics, verbose, jobs, builtins, doctests, max-
    complexity.

    --config=path       user config file location (default:
                        C:\PortableApps\Home\.flake8)

Seems comprehensive. I bet a bunch of those would be quite handy in time, but right now, it looked like I wanted --select to limit the kinds of complaints. Based on the example, I figured I could use a single letter to include a whole class of complaints. And it looked like --exclude would keep flake8 from examining BeautifulSoup:

LibraryHippo>flake8 App --select=F --exclude=BeautifulSoup.py
App\cardchecker.py:6:1: F401 'DeadlineExceededError' imported but unused
App\cardchecker.py:61:13: F841 local variable 'name' is assigned to but never used
App\cardchecker.py:71:37: F821 undefined name 'clock'

There were complaints about other files, but the total count was down to 31, which was quite manageable. The "F" codes come from PyFlakes, and don't necessarily mean "fatal" like I first thought. Some, such as F841, are valid problems, but hardly catastrophic. Still, it was a small matter to fix all the "F"s in the code. Later on, I went back, expanding to changing the --select to F,E and eventually omitting it altogther.

Command-line arguments are so tedious

Always specifying options to ignore files or set maximum line lengths (79 is just too short even for an editor taking up the left half of my screen) can get old fast, so flake8 lets you put ever-repeated settings in a file. As promised, the following setup.cfg file lets me just run flake8 App and get the same results as above:

[flake8]
exclude = BeautifulSoup.py
select = F

Handy extension: naming

It's possible to write extensions for flake8, and a number already exist. In fact, mccabe looks to be implemented as an extension (and maybe the others, I didn't check). On a lark, I went looking and found the pep8-naming extension, which checks PEP 8 naming conventions (something not fully covered by pep8, I guess). Installation via pip was simple and now
flake8 --version reports

2.2.2 (pep8: 1.5.7, pyflakes: 0.8.1, mccabe: 0.2.1, naming: 0.2.2)
CPython 2.7.2 on Windows

(And just running flake8 shows a whole bunch of "N8*" complaints such as

App\wpl.py:227:17: N806 variable in function should be lowercase
App\gael\memcache.py:16:11: N801 class names should use CapWords convention

But that's my problem to deal with.)

Writing new extensions doesn't look to be too difficult, if anyone listening is interested in helping the tool spell-check my symbol names (and maybe comments).

Impressions

A very useful static analysis tool that is easy to set up, runs quickly, and is configurable enough to start working on almost any codebase. So far the complaint descriptions seem good, and I can quickly resolve reported problems without consulting a manual. The extension ecosystem provides even more power, if you need it.

Will I Use It?

Absolutely, and you should too.

I'm so committed to it that I wrote a "deploy.bat" file that will only deploy to Google App Engine if flake8 doesn't complain.

Making a Duck-Dog using FakeItEasy's CallsBaseMethod(s)

Fri, 29 Aug 2014 00:00:00 +0000

A while back, Roman Turovskyy wrote FakeItEasy: Be Careful When Wrapping an Existing Object, an interesting post highlighting some of the difficulties of faking classes (as opposed to interfaces, which by virtue of having no behaviour of their own, are quite a bit more predictable). It's well-written and I enjoyed it, but he overlooked a small point. I figured others may easily make the same omission, so I'd like to explain why the example from that post works as it does, and to provide an alternative solution.

Mr. Turovskyy supposes we want to fake out the following Dog class:

public class Dog
{
    public virtual string Bark()
    {
        return "Bark!";
    }
    public virtual string BarkBark()
    {
        return Bark() + Bark();
    }
}

He notes that the default behaviour of a fake Dog, as made by dog = A.Fake<Dog>(), is for both Bark and BarkBark to return the empty string, which is not always desirable.

His next step is to create a fake by wrapping a Dog object:

Dog realDog = newDog();
Dog dog = A.Fake<Dog>(x => x.Wrapping(realDog));

Now Bark and BarkBark return the original (expected) strings.

Then Mr. Turovskyy addresses customizing the fake object to change the way it barks.

Here, things break down a little bit. His desired goal, of using A.CallTo to override Bark to return "Quack!" works, but when BarkBark is called, it still returns "Bark!Bark!".

He comments

For those who know how virtual methods work, this looks very counter-intuitive.

And that's completely true. The problem is that when a fake wraps an object, we're using a composition model, not inheritance. Thus the fake Dog knows to call the real dog's BarkBark method, but the real dog doesn't know about the fake Dog at all, so it just calls its own Bark method, which returns "Bark!".

Using the Wrapping option and then overriding Bark on the fake is equivalent to writing this manual wrapper:

public class WrappingDog: Dog
{
    private readonly Dog realDog;

    public WrappingDog(Dog realDog)
    {
        this.realDog = realDog;
    }

    public override string Bark()
    {
        return "Quack!";
    }

    public override string BarkBark()
    {
        return this.realDog.BarkBark();
    }
}

Mr. Turovskyy suggests getting the desired behaviour by writing a manual FakeDog that overrides Bark, which will work, but is tedious and discards the benefits that FakeItEasy can provide.

Another Way to Access Original Behaviour

FakeItEasy can be used to get the desired behaviour. It provides a CallsBaseMethod method when configuring a fake. It does just what you'd hope it would. Witness:

Dog dog = A.Fake<Dog>();
A.CallTo(() => dog.BarkBark()).CallsBaseMethod();

This tells the fake Dog to call the real Dog.BarkBark when its BarkBark method is invoked. When this is combined with an override for Bark, we can write this passing test:

[Test]
public void BarkBark_CallsBaseMethod_UsesOverriddenBark()
{
    Dog dog = A.Fake<Dog>();

    A.CallTo(() => dog.BarkBark()).CallsBaseMethod();
    A.CallTo(() => dog.Bark()).Returns("Quack!");

    string result = dog.BarkBark();

    Assert.That(result, Is.EqualTo("Quack!Quack!"));
}

Call Base Methods More Conveniently

As of FakeItEasy 1.24.0, there's an additional way to do this, and it may appeal more to users who want many methods on their fake to call the original class's version. There's a new fake creation option called CallsBaseMethods. It was proposed by Aleksander Heintz, who also provided nearly the complete implementation. When used, it will cause every method on a fake to delegate to the faked type's implementation, if there is one. So the previous test could be written as

[Test]
public void BarkBark_CallsBaseMethod_UsesOverriddenBark()
{
    Dog dog = A.Fake<Dog>(options => options.CallsBaseMethods());

    A.CallTo(() => dog.Bark()).Returns("Quack!");

    string result = dog.BarkBark();

    Assert.That(result, Is.EqualTo("Quack!Quack!"));
}

The change in the first line means that when dog is created, every method will delegate to the version on Dog.

Then Bark is overridden, and the base BarkBark is able to use the new version.

Now we can realize our dream of having a Seussian DuckDog:

Automatically Printing Rake (or other Ruby) Variables

Thu, 05 Jun 2014 00:00:00 +0000

The FakeItEasy rakefile contains a vars target (brainchild of Adam Ralph) that can be used to print out the local variables defined in the script. Mostly these are static variables, such as the path to the NUnit command, but some, such as the upcoming FakeItEasy version, are computed. Logging these computed variables can help debug misbehaving builds.

If ever something goes wrong, we can check the TeamCity build log and see something like this:

assembly_info:     Source/CommonAssemblyInfo.cs
mspec_command:     Source/packages/Machine.Specifications.0.8.0/tools/mspec-clr4.exe
nuget_command:     Source/packages/NuGet.CommandLine.2.8.0/tools/NuGet.exe
nunit_command:     Source/packages/NUnit.Runners.2.6.3/tools/nunit-console.exe
nuspec:            Source/FakeItEasy.nuspec
output_folder:     Build
repo:              FakeItEasy/FakeItEasy
solution:          Source/FakeItEasy.sln
ssl_cert_file_url: http://curl.haxx.se/ca/cacert.pem
version:           1.21.0

integration_tests:
  Source/FakeItEasy.IntegrationTests/bin/Release/FakeItEasy.IntegrationTests.dll
  Source/FakeItEasy.IntegrationTests.VB/bin/Release/FakeItEasy.IntegrationTests.VB.dll

release_body:
  * **Changed**: _<description>_ - _#<issue number>_
  * **New**: _<description>_ - _#<issue number>_
  * **Fixed**: _<description>_ - _#<issue number>_
  
  With special thanks for contributions to this release from:
  
  * _<user's actual name>_ - _@<github_userid>_

release_issue_body:
  **Ready** when all other issues forming part of the release are **Done**.
  
  - [ ] run code analysis in VS in *Release* mode and address violations (send a regular PR which must be merged before continuing)
  - [ ] check build, update draft release in [GitHub UI](https://github.com/FakeItEasy/FakeItEasy/releases)
         including release notes, mentioning non-owner contributors, if any
…

Originally, the vars task was hand-written, so whenever we added a new variable we had to update the task. Not too long ago, I added a new variable, and (surprisingly) remembered to update vars. However, Adam noticed that I had put the puts statement in the task in the wrong place, so the declaration order didn't match the printed order. A small thing, but the small things matter.

So, we had a chat about the best way to present the variables. Declaration order is attractive, but I pushed a different approach: first, separating the variables with short values, such as assembly_info, from variables with long values, such as release_body. This keeps the short values from becoming lost in the noise of the longer ones. Second: sort lexicographically within the groups, to aid scanning.

We came to an agreement, but as I started to make the change, I thought, "Why make humans worry about this? Computers are good at partitioning and sorting." So, after a quick search for something that would allow printing of local Ruby variables, I found local_variables, and rewrote the task:

desc "Print all variables"
task :vars do
  print_vars(local_variables.sort.map { |name| [name.to_s, (eval name.to_s)] })  
end

def print_vars(variables)
  
  scalars = []
  vectors = []

  variables.each { |name, value|
    if value.respond_to?('each')
      vectors << [name, value.map { |v| v.to_s }]
    else
      string_value = value.to_s
      lines = string_value.lines
      if lines.length > 1
        vectors << [name, lines]
      else
        scalars << [name, string_value]
      end
    end
  }

  scalar_name_column_width = scalars.map { |s| s[0].length }.max
  scalars.each { |name, value| 
    puts "#{name}:#{' ' * (scalar_name_column_width - name.length)} #{value}"
  }

  puts
  vectors.each { |name, value| 
    puts "#{name}:"
    puts value.map {|v| "  " + v }
    puts ""
  }
end

Points of interest:

The task delegates to a function right away, to avoid creating new variables that would be found by local_variables.
The first thing the method does is partition variables into "scalars", to be rendered on the same line as the variable name, and "vectors", which have multiple elements or lines, and are rendered below the variable name.
As a bonus, the scalar variable names padded so the values can all land on a "tab stop"

Best of all, now we can add rake variables willy-nilly, with nary a thought about printing them out. It just happens.

Debugging a Pickle of a Stack Overflow on Google App Engine

Mon, 05 May 2014 00:00:00 +0000

A few days ago, a user e-mailed me a bug report for LibraryHippo. For the previous 55 days, she'd been receiving the same (erroneous) morning e-mail about what library materials she had due. However, when she checked her family's account summary on the web page, it was correct.

(The exact cause of the problem won't be of interest to many people, but I thought the way it presented, and how I diagnosed it, might help someone out. Read on!)

I checked the logs, and sure enough, there was an error. Sort of like this:

I 2014-04-28 14:10:43.429 checking [patron name redacted] Waterloo
I 2014-04-28 14:10:47.550 saving checked card for [patron name redacted]
E 2014-04-28 14:10:51.061 Failed to save checked card. Continuing.
Traceback (most recent call last):
  File "/base/data/home/apps/s~libraryhippo27/1.368776574735783966/libraryhippo.py", line 380, in save_checked_card
    checked_card.payload = card_status
  File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/ext/db/__init__.py", line 614, in __set__
    value = self.validate(value)
  File "/base/data/home/apps/s~libraryhippo27/1.368776574735783966/gael/objectproperty.py", line 11, in validate
    result = pickle.dumps(value)
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 1374, in dumps
    Pickler(file, protocol).dump(obj)
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 224, in dump
    self.save(obj)
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 286, in save
    f(self, obj) # Call unbound method with explicit self
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 725, in save_inst
    save(stuff)
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 286, in save
    f(self, obj) # Call unbound method with explicit self

[about 80 lines of stack trace elided]

  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 663, in _batch_setitems
    save(v)
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 286, in save
    f(self, obj) # Call unbound method with explicit self
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 725, in save_inst
    save(stuff)
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 286, in save
    f(self, obj) # Call unbound method with explicit self
  File "/base/data/home/runtimes/python27/python27_dist/lib/python2.7/pickle.py", line 649, in save_dict
    self._batch_setitems(obj.iteritems())
  File "/base/data/home/runtimes/python27/python27_dist/...(length 98720)
I 2014-04-28 14:10:51.275 Saved; key: __appstats__:043300, part: 190 bytes, full: 65479 bytes, overhead: 0.004 + 0.005; link: http://libraryhippo27.appspot.com/_ah/stats/details?time=1398708643356

Whenever LibraryHippo checks a patron's library card, it saves the results to the datastore to be used to construct the next day's e-mails, but an inability to save doesn't keep the results from being displayed on the web page. So that part made sense.

The next step was to figure out what was going wrong with the save. The logs indicated that pickle was using more stack frames than were available.

I try to debug it

I added a copy of the offending card to my family's account on the live site. Same problem. Then I fired up the dev environment at home and did the same thing. Everything worked like a charm.

That was unexpected. So, as a last resort, I started thinking.

Why so deep?

The structure that was being pickled (CardStatus) was quite flat. Here are the involved classes' definitions. Unless noted otherwise, everything is a string or datetime:

class CardStatus:
    def __init__(self, card, items=None, holds=None):

        self.library_name = card.library.name
        self.patron_name = card.name
        self.items = items or []  # Items
        self.holds = holds or []  # Holds
        self.info = []            # strings
        self.expires = datetime.date.max

class Thing():
    def __init__(self, library, card):

        self.library_name = library.name
        self.user = card.name
        self.title = ''
        self.author = ''
        self.url = ''
        self.status = ''
        self.status_notes = []    # strings

class Hold(Thing):
    def __init__(self, library, card):
        Thing.__init__(self, library, card)

        self.pickup = ''
        self.holds_url = ''
        self.expires = datetime.date.max

class Item(Thing):
    def __init__(self, library, card):
        Thing.__init__(self, library, card)

        self.items_url = ''

So, one level for the CardStatus, one for Thing, one for Hold (or Item), one for a list, and one for the status_notes strings in the list. That's 5 levels. And probably pickle encodes a dict in a few of the of the complex types. Let's be generous and say 10 levels, each of which take maybe 5 nested pickle functions. That's about

Plus however deep we are in the stack before the pickling happens. That shouldn't be more than 100.

How deep is too deep?

Popular wisdom on the web seems to be to increase the recursion limit when pickle runs into these kinds of problems. I was loath to do this, as I'd be constantly worrying about what depth to allow and whether it'd be enough and so on.

While I dithered over that, my wife called to me from the television room, "Just set the limit higher. That should help your user for now and it will give you more time to work on the problem."

So I did. I was worried that the App Engine runtime wouldn't let me change the recursion limit, so I used sys.getrecursionlimit to log the depth, sys.setrecursionlimit, and sys.getrecursionlimit again to verify.

Turns out that:

The default recursion limit on App Engine's environment is 800.
You can change the limit. I went up to 20000.
In the dev environment the limit is 1000.

The higher limit on the production server fixed things. I relaxed a little, and started thinking.

Maybe the 800/1000 difference accounted for things working at home, but not in production. I used sys.setrecursionlimit to change the limit at home, and reproduced the error. Huzzah! Now I could move more quickly.

Inserting diagnostics into pickle

Back to the question of why pickle was recursing so deeply. I don't routinely debug Python, relying instead on the power of logging statements. Thus, I decided to provide a custom pickler that did normal pickling things, but that also, for every object pickled, logged the stack depth, the object type, and its representation:

import pickle
import logging
import traceback

class SpyingPickler(pickle.Pickler, object):
    def save(self, obj):
        logging.info("depth: %d, obj_type: %s, obj: %s",
                     len(traceback.extract_stack()),
                     type(obj), repr(obj))
        super(SpyingPickler, self).save(obj)

I ran this, and got reams of data. Scads and scads and scads, including what looked like to be large HTML documents. So I took out the repr(obj) and repeated. This was more manageable.

…
depth: 176, obj_type: <class 'BeautifulSoup.NavigableString'>
depth: 179, obj_type: <type 'function'>
depth: 179, obj_type: <type 'tuple'>
depth: 182, obj_type: <type 'type'>
depth: 182, obj_type: <type 'type'>
depth: 182, obj_type: <type 'unicode'>
…

Already we can see that we're quite deep in the stack, but the real surprise was the BeautifulSoup.NavigableString. LibraryHippo uses BeautifulSoup to scrape the libraries' web pages. A NavigableString is basically a Unicode string plus navigation. To support the navigation, the instance points at what looks to be a DOM model of the entire parsed HTML page. That explains the deep deep recursion.

The offending objects were in the pickup field of the Hold class. A quick fix to ensure we're storing a plain string, and the problem was resolved.

What a difference

Aside from the obvious effect of correct e-mails, I was curious to see what other differences this change made.

Before the fix, the serialization descended to a stack depth of 892, and produced a 546221-byte blob. After, the maximum depth is 52, and the blob size is 10779 bytes. So everyone should benefit a little from lower resource usage and quicker card-checking. Fortunately, LibraryHippo isn't popular enough to exceed the free quotas, so I wasn't paying extra for compute or storage. Then again, if I had been, maybe I would've noticed the problem before a user did.

User-Sourced Calendar Feeds for Waterloo Yard Waste Pickup

Wed, 16 Apr 2014 00:00:00 +0000

(Thanks to Jon Udell, whose insightful posts are the only reason this would ever have occurred to me.)

I live in Waterloo, Ontario, a city with weekly residential waste collection. My collection day is Monday. In the warm months, there's an additional biweekly (that's every 2 weeks, not twice a week) collection of what's called yard waste: grass clippings, raked-up leaves, tree branches, and so on.

People in my area (including me) have trouble remembering which weeks are yard waste weeks. This means that every two weeks I get to see collections of plant material left at the curb outside people's homes and then brought in a day or two later, only to reappear the next week.

I use tools to augment my memory. Every year, at the beginning of the warm season, I visit the Region of Waterloo's website where I can learn about their Yard waste residential collection program. Here I find links to two PDFs: a pretty version of the schedule for Waterloo, and an "accessible" version.

I look at one of those schedules, and I create a recurrning Google Calendar event. Then my phone tells me on Sunday night whether to haul the tree parts to the street. It works really well.

However, every year, I've wished that the Region provided an .iCalendar feed or created a Google Calendar for me so I wouldn't have to do this. But I haven't done more than wish.

This year, I'm doing more. For starters, I created a few Google Calendars. One for me (and my fellow Monday-pickup people), and four for everyone else in Waterloo (and Cambridge). The Region's web site gave me start and end weeks for pickups, so it was very easy to make a biweekly repeating event, using these Google Calendar settings:

Lo and behold, it shows up in my calendar:

I created the Tuesday through Friday calendars by making the obvious modification to the schedule above.

I put all the calendars on a separate page that I intend to maintain until the Region provides replacements. Or I move. Go! Get one for your collection day.

Next, I'm going to pester the Region, showing them how easy it was to do this and to see if they'd be willing to carry on with the work next year. If something comes of it, I'll let you know.

Limit FakeItEasy extension scanning with a bootstrapper

Thu, 06 Mar 2014 00:00:00 +0000

As of version 1.18.0, a client-supplied bootstrapper can be used to determine which external assembly files are scanned during startup.

Last time, I talked about how FakeItEasy extension scanning had improved in version 1.13.0. While this change has dramatically improved startup times in many situations, we recently received a comment from one of our valued clients (and subsequently a pull request with a proposed solution), detailing a situation where startup was taking about 13 seconds, mostly due to a huge number of assemblies in the working directory. Disabling shadow copy creation by the test runner alleviated the pain, but the incident prompted a re-examination of the issue.

While disabling shadow copies should resolve most slow startup problems caused by excessive working directory assemblies, and it may improve performance in other ways, recommending this to clients has always felt like a bit of a dodge to me, essentially pushing the problem off to someone else. There was also the lingering fear that someone would come back with a reason why the shadow copies were necessary.

We wanted to provide FakeItEasy's clients with a little more control over the process of scanning for assemblies. So, we've implemented the originally-proposed bootstrapper solution.

Using a custom bootstrapper

By default, after scanning all FakeItEasy-referencing assemblies currently loaded in the AppDomain, FakeItEasy 1.18.0 will examine all DLLs in the working directory. This behaviour can be changed by including in the AppDomain a class that implements FakeItEasy.IBootstrapper. As I write, this is the only behaviour that the bootstrapper controls:

/// <summary>
/// Provides a list of assembly file names to scan for extension points, such as
/// <see cref="IDummyDefinition"/>s, <see cref="IArgumentValueFormatter"/>s, and 
/// <see cref="IFakeConfigurator"/>s.
/// </summary>
/// <returns>
/// A list of absolute paths pointing to assemblies to scan for extension points.
/// </returns>
IEnumerable<string> GetAssemblyFileNamesToScanForExtensions();</code></pre>

The best way to implement the interface is to **extend
`FakeItEasy.DefaultBootstrapper`**. This class defines the default
FakeItEasy setup behaviour, so using it as a base allows
clients to customize only those aspects of the initialization that
matter to them.

While any list of assembly files can be provided by
`GetAssemblyFileNamesToScanForExtensions`, I expect that most
extensions that are defined will already be loaded in the current
AppDomain, so the most common customization will be to disable
external assembly scanning, like so:

<pre><code class="csharp">public class NoExternalScanningBootstrapper : FakeItEasy.DefaultBootstrapper
{
    public override IEnumerable<string> GetAssemblyFilenamesToScanForExtensions()
    {
        return Enumerable.Empty<string>();
    }
}

Of course, if there were extensions defined in an external assembly file or two, the GetAssemblyFilenamesToScanForExtensions implementation could return the paths to just those assemblies.

Better formatter auto-discovery in FakeItEasy 1.13.0

Mon, 08 Jul 2013 00:00:00 +0000

A few weeks ago, I wrote about the problems that FakeItEasy's assembly scanning was causing while it was looking for user-defined extensions. To recap, FakeItEasy was scanning all assemblies in the AppDomain and the working directory, looking for types that implemented IArgumentValueFormatter, IDummyDefinition, or IFakeConfigurator. This process was quite slow. Worse, it raised LoaderLock exceptions when debugging, and Runtime errors anytime I ran my tests using the ReSharper test runner.

At that time, I'd opened issue130, intended to allow configuration of the scanning procedure. I'm happy to say that the issue has been closed "no fix". Instead, I've contributed the fix for Issue 133 — Improved performance of assembly scanning. It doesn't introduce any configuration options, but streamlines the scanning process.

The original behaviour was:

find all the DLLs in the application directory
load all the found DLLs
find the distinct assemblies among those loaded from the directory and those already in the AppDomain
scan each assembly and add all the types to a list

The new behaviour, heavily inspired by Nancy's bootstrapper-finding code, is:

find all the DLLs in the application directory
discard DLLs that are already part of the AppDomain - We don't even have to crack these files open again, since we already know everything about them. Note that this check examines the absolute paths to the DLL and the loaded assembly, and will be fooled by shadow copying. So, if your test runner makes shadow copies, this time won't be saved. I turned off shadow copying with no ill effects (and a tremendous speedup), but your mileage may vary.
load each remaining DLL for reflection only - This may be faster, and it may not, but it has another big advantage - it doesn't cause any of the code in the assembly to execute. (It was the execution of the assembly code that caused my LoaderLock and Runtime errors.)
for each assembly that references FakeItEasy, fully load it - If we don't do this, we can't scan for all the types in the assembly because

When using the ReflectionOnly APIs, dependent assemblies must be pre-loaded or loaded on demand through the ReflectionOnlyAssemblyResolve event

according to the error I got when I tried it. Note that excluding assemblies that don't reference FakeItEasy means we only examine assemblies that could possibly define formatting/dummy/configuration extensions, cutting down on the scanning time.
scan each of the following, remembering all contained types:
- the assemblies we just loaded from files,
- the AppDomain assemblies that reference FakeItEasy, and
- FakeItEasy - We need to include FakeItEasy explicitly because it defines its own formatter extensions, and since we're otherwise only looking at assemblies that reference FakeItEasy, we'd miss it.

This new scanning behaviour has been released in the FakeItEasy 1.13.0 build, and has been a boon to me already. I'm enjoying the faster test runs (0.534 seconds for my first test, versus 1.822 (or more)) and the improved stability of the test runner. NuGet it now.