Building the Sleigh While Flying It

"B, a little help?" Santa's voice echoed through the toymaker's headquarters, its pitch a little higher than usual. Binky the Elf left her station and cracked open the boss's door. "What's up, Nick?" she replied, nonchalantly. Santa was squinting at the monitor in front of him, where several lines of error messages kept flooding the terminal.

"I think there's something wrong with the reindeers."

The famous Christmas Reindeers are, of course, robots. As a lover of all living things, Santa could never bring himself to force animals into such a strenuous journey each year. Besides, how else do you think they can travel that fast?

Binky sighed and glanced over Santa's right shoulder. The world population had just surpassed 8 billion, so they had to spend a good part of the year profiling and optimizing the reindeers' code for speed. "I thought you tested it back at All Hallows Eve", the elf cried. Santa looked down, his face redder than his coat. "I was going to, but Jack took me trick or treating instead", he muttered.

Binky raised an eyebrow. With that kind of care, it was a Christmas Miracle this code compiled in the first place. Thinking of the kids, she decided not to pursue the argument and instead put her energy into finding and fixing the issue. The error messages were cryptic, at best:

    
    Undefined subroutine &Class::MOP::Class:::after called at /home/santaclaus/.plenv/versions/5.36.0/lib/perl5/site_perl/5.36.0/x86_64-linux/Class/MOP/Method/Wrapped.pm line 57.
    Reindeer::Prancer::_wrapped_dash_away(Reindeer::Prancer=HASH(0x1383a6160)) called at /home/santaclaus/.plenv/versions/5.36.0/lib/perl5/site_perl/5.36.0/x86_64-linux//Class/MOP/Method/Wrapped.pm line 97
    Reindeer::Prancer::dash_away(Reindeer::Prancer=HASH(0x1383a6160)) called at christmas.pl line 1225
    

"Huh.", the elf frowned. Reindeers were controlled by complex Moose classes, but method modifiers such as 'before', 'after' and 'around' were pretty standard. It made no sense that "after" was not defined. Line 1225 of christmas.pl, was also pretty straightforward:

$reindeer->dash_away();

Binky and Santa spent a little while staring at the source code. Everything looked fine, but the code was still failing. Finally, Binky broke the silence: "Did you try dumping $reindeer before that call?" she suggested. "I did, but look!", the old man scrolled up the terminal window and pointed at a line that said:

        $VAR1 = bless( {}, 'Reindeer::Prancer' );

"It's just showing the bless() command, an empty hash reference and the class name. How am I supposed to work with that?" Santa whimpered. "That's because you're using Data::Dumper, boss." A faint smile crept into Binky's lips. It wasn't every day she was able to teach Father Christmas himself something new. She continued. "Data::Dumper is best for serializing. If you want to inspect the data yourself, you should use Data::Printer instead."

Santa Claus' eyes widened. "Data::Printer? What kind of sorcery is that?" The elf signaled him to scooch over so she could reach the keyboard herself. As she typed cpanm Data::Printer, she said: "It's a module that dumps variables in a way meant to be read by an actual human trying to debug code. Don't worry, it's super light and fast - zero deps and all. See? It's already installed." Then she fired up the editor and replaced the line that said:

use Data::Dumper; say Dumper($reindeer);

with:

use DDP; p $reindeer;

They gave it another go and the result was quite different:

    
    Reindeer::Prancer  {
         parents: Reindeer
         roles (1): FlyingMagic
         attributes (2): name, sleigh
         public methods (24):
             dash_away, DESTROY, meta, new
             Carp:
                 confess
             Class::MOP::Class:
                 :after
             FlyingMagic:
                 liftoff
             Moose:
                 after, around, augment, before, extends, has, inner, override, super, with
             Moose::Object:
                 BUILDALL, BUILDARGS, DEMOLISHALL, does, DOES, dump
             Scalar::Util:
                 blessed
         private methods (1): _build_name
         method modifiers (1):
             after dash_away <undefined coderef>
         internals: {}
     }
  

The terminal lit up like a Christmas Tree. They could see the full class hierarchy, applied roles, attributes, public and private methods - everything! Santa's eyes sparkled. "Ho! Ho! Ho! I know what's wrong." He pointed at the line that said after dash_away: <undefined coderef> in bright red. They searched the source code for 'after "dash_away"' and quickly found the only entry, that read:

after 'dash_away' => \&lifftoff;

They took another look at the Data::Printer output searching for that method. Santa quickly spotted it coming from the FlyingMagic role, but it was written differently. "A typo! Someone was naughty on that code review." They fixed the typo and ran it again. It worked! One by one the reindeers started whirring. Santa was about to jump on the sleigh for a final test-drive when the elf interrupted the program. "What is it, B?" the old man asked.

Binky was staring at the terminal again. "It's leaking memory. The way things are, the sleigh will crash before you even reach the Atlantic. Hold on." The elf added a bunch of p() statements throughout the code. Santa Claus looked bewildered. "What are you doing? There will be so much stuff in the output we won't be able to make any of it out!", he scoffed.

"Sure we will." Binky replied without taking her eyes off the monitor. "We'll control what prints what on the .dataprinter file". She created a new file called ".dataprinter" on the root of the project path, then made it look something like this:

    
    show_refcount = 1
    theme = Material

    [Sleigh::Engine]
        class.expand = 0
    
    [Toys::Storage::MagicBag]
        filters = DB
    
    [Reindeer]
        class.stringify = 0
        class.show_wrapped = 0
        class.inherited = none
        output = /var/log/christmas/reindeer.data
    

Binky went on to explain that you could place global settings for Data::Printer at the top of that file, like setting a theme and showing refcounts, then create more specific rules that apply only to certain caller packages. In this case, any p() statements made inside Sleigh::Engine would not expand objects, showing only the class name and (as per the global setting) the refcount. On the other hand, calls to p() inside Toys::Storage::MagicBag would be subject to all the filters set on Data::Printer::Filters::DB, useful to see database connection statuses, prepared statements, result sources and sets from DBI, DBIx::Class and more.

Finally, calls to p() made inside Reindeer.pm would not attempt to stringify objects that have a subroutine as_string, to_string or similar, nor will they show wrapped method modifiers or methods inherited from parent classes. Even so, that particular output is in a hot codepath and can get pretty big, so instead of printing to STDERR, it will write to the custom /var/log/christmas/reindeer.data file.

"We could even put all those settings in a custom profile package and upload it to CPAN or whatever, but right now a .dataprinter file is more than enough." They tried running the program again and, sure enough, the output read:

    
    Sleigh (refcount: 10)
    Sleigh (refcount: 10)
    Sleigh (refcount: 10)
    

Santa was puzzled. "10 refcounts on the sleigh? We must have a circular reference somewhere. What's going on on that Reindeer log file?" Binky opened it, but it looked pretty much the same: several reindeer objects just like before, except this time without the inherited methods but with a refcount next to each data, just like they asked:

    
    Reindeer::Vixen  {
         parents: Reindeer
         roles (1): FlyingMagic
         attributes (2): name, sleigh
         public methods (4):
             dash_away, DESTROY, meta, new
         private methods (1): _build_name
         internals: {
             sleigh    Sleigh (refcount: 10)
         }
     }
  

Santa sighed. "If only that Data::Printer of yours could signal weak references..." Binky's eyes widened as she stared at him. "Nick, you're a genius!" The old man chuckled. "Me? What did I do?" The elf went on. "Data::Printer DOES show when it's looking at a weak ref. The fact that we don't see it means that Sleigh object right there was NOT weakened." They opened the reindeer class in the editor and replaced the line that read:

has 'sleigh', is => 'rw', isa => 'Sleigh';

with:

has 'sleigh', is => 'rw', isa => 'Sleigh', weak_ref => 1;

They fired up the program again. The reindeers whirred and clanked for a few seconds, then Rudolph's nose lit up, signaling the restart was complete and they were all ready to fly. Santa's heartbeat kicked up a notch as Binky opened the logs to see what it showed:

    
    Reindeer::Vixen  {
         parents: Reindeer
         roles (1): FlyingMagic
         attributes (2): name, sleigh
         public methods (4):
             dash_away, DESTROY, meta, new
         private methods (1): _build_name
         internals: {
             sleigh    Sleigh (weak)
         }
     }
  

The sleigh references were weak and no refcount was showing. "Yes!" the elf fell back into her chair and breathed a sigh of relief. "Do we remove the p() statements now that everything is fine?" asked Santa. "We can, sure - but if you think they're in good debugging spots you can just add quiet = 1 to each section of the .dataprinter file and any calls to p() will quickly return not printing anything. We can even add a live_update = 1 and Data::Printer will automatically watch the .dataprinter file and reload it whenever we change it without needing to restart the program."

The old man thanked his friend as she rose up to leave. Binky was almost at the door when she turned and realized Santa was still at the computer. "You're gonna play with the output colors and make a new theme for Data::Printer now, aren't you?"

Santa grinned. This was going to be a Merry Christmas after all.