DBlog

The Wonderful And Frightening World of DepressionBot Development

[dbotlog]

Users Module and Undefined Primary Keys

In the last couple of days I've been rewriting the users module to use the databank library.

The users module is one which automatically tracks users on the servers through which channels they frequent and their various aliases - while it doesn't provide much functionality on its own, its rich API allows other modules to be much more effective in their operations (for example storing stats for a user using several aliases under one account).

The rewrite has gone smoothly for the most part, as it's been relatively easy to move the code over and I've been impressed by the number of efficiency improvements I've been able to make along the way.

However, for the last hour or so I've been hitting my head against the wall over an intensely peculiar bug which came about as soon as I started testing with multiple users.

-!- batman62 is now known as batman64 ~alias batman64 batman64 is an alias of batman62 -!- lslater is now known as lslatest ~alias batman64 batman64 does not currently exist as an alias or known user.

So for some reason, a nick change was processed perfectly until a completely different user changed their nickname, whereupon the stored alias for the original user would disappear. This made no sense, given the two nick changes were entirely separate events operating on entirely different data records.

After a lot of anger and several nearly-executed threats to quit computing and become a watermelon farmer, I decided to print out the UUID of the records.

User records in the new system are stored with a randomly generated unique ID, and we then retrieve the record we want by searching for 'server' and 'username' to uniquely identify a record.

As it turns out, in the event of a nick change I was saving a copy of the user record with the additional alias in the database with a primary key of 'undefined' - this being because I was attempting to use user.id, while the actual ID was being stored in user.uuid. When this was looked up by 'server' and 'username,' the record with the primary key of 'undefined' was being returned (with the correct list of aliases).

However, when another nick change took place from another user, the old 'undefined' record was being replaced with the new one. This meant that a search on the original nick would turn up the original record with the correct UUID, unmodified and therefore without aliases. It was fixed by simply changing my use of 'id' to 'uuid,' as it was stored in the record.

~reality

[dbotlog]

An Owl in the System

Eagle eyed depressionbot users (of which there are many) would have noticed the glaring errors issued by express when trying to access userlists views on the web interface earlier this week.

Following the solve, I thought it might be interesting enough for a blog post and provide a nice follow up from my introduction to the stats module. If you haven't read it already, you might want to consider reading that post for a brief overview of how the stats module works first, for some background.

TypeError: Object #<Object> has no method 'get' at api.getChanStats.reply.request.server at pages./user/:connection/:channel

So back to the story at hand; as we have enough context to now deduce that the error definitely seemed to be caused by one of these fields. A quick inspection of the error and stack trace provided by express when trying to render the channel stats view would seem to have indicated that these fields is missing its "get" function. Not quite realizing the full extent of the bug, @reality switched the bot to debug mode (via a nifty command that I'm sure he'll tell you about some time) while I grappled to run the most basic stats command to check the module was still alive and sure enough it spewed the same error in to the channel.

~lines

> - Error in ~lines:

> - Message: TypeError: Object #<Object> has no method 'get'

Surely they can't be missing? Why would this suddenly appear now, I hadn't pushed anything new to stats since a language update at the end of the last month, so nothing has changed with regards to the way the module's structures are laid out or loaded, and I hadn't touched the user and channel templates since I added a seven day rolling frequency field for channels almost a month prior. ~ajs however, revealed that they really were missing and I was now compelled to find out why.

~ajs Object.keys(dbot.db.userStats.aberwiki.sam["#oaosidl"].lines)

> name,data,time,format,getRaw,get,__add,add,merge,__merge,toString

~ajs Object.keys(dbot.db.chanStats.aberwiki["#42"].lines)

> name,data,time

So evidently the onLoad was correctly attaching the additional functions to each field in the user objects, but for some reason it seemed almost as though it were skipping over the loop for the chanStats store. Obviously leaving these fields without their enhancing functionality, they were left dumb and unable to respond to the likes of the get and add functions expected of them.

Loading up my local version of depressionbot and connecting to the sever, I couldn't seem to reproduce the problem. stats commands worked and the web interface appeared in all of its d3-and-datatables glory. Perhaps my repositories were out of date? They were, which is unsurprising given the pace of depressionbot development lately. Yet I still couldn't reproduce the errors, did the current instance of depressionbot @reality was running differ in some way from the repo? We'd already established that another instance of the software was not suffering problems either. Confirming that depressionbot functioned fine with a clean database, I requested a copy of the prestigious dbot-prime database and was promptly mailed a half megabyte json file and instantly the error was reproducible. The issue was the database?!

We waded through the length channel stats objects that had been serialized in to the json file but could not spot anything that seemed out of place at all. Obviously the file couldn't be corrupted or invalid (damn commas) as the bot would fail to load at all, so the issue must be far more subtle. A quick and dirty naive debugging attempt placed a console.log line immediately after the completion of the userStats loop in the module's onLoad.

It was never called.

The issue was not with the channel objects at all, the onLoad was aborting silently whilst processing the user objects all this time. But how was that possible? All the users appeared to be loading fine and functions that relied purely on userStats objects completed successfully. If it was aborting, it didn't seem to have any impact on the functionality of user statistics. Continuing my leisurely printing style debugging, I moved the console.log back a few lines, in to the heart of the travesty that is the userStats onLoad megaloop, this time printing the components of the "address" to the current user object field we were trying to apply the model template to; the server, user, channel and field name itself.

As various combinations of rooms and names flicked past I was about to deem the venture as a useless endeavour and at this point was happily considering "just nuking" the database so we could all get on with our evening.

Until I noticed one line of output.

aberwiki #oaosidl hootle_testing data

Data? But the user template definitely doesn't specify any field called data? Immediately I realized what had happened and what I had done.

Days before, I was poking around the database with ~ajs to try and find a solution for another bug (looking at the length of this post already, definitely a story for another day) but the rough gist is when a user has two nicks that the bot sees as separate (either because the bot was not in channel at the time they changed to a new nick, or they connected to IRC with a new nick from usual), the user will also have two separate stats profiles (ie. the two different keys under different names in userStats, not to be confused with the profiles module, although they'll have two of those as well!). It's expected that if the user were to then change from one of these "primary" nicks to the other, the users module merges all the aliases for both of those users together; the bot now sees those two names as the same person, but under some specific circumstances, the stats module will fail to merge those two stats profiles together, leaving both "primary" nicks in the database.

I had successfully reproduced this with a user called hootle_testing; joining the server under this new name, saying hello (to initiate a new stats profile), leaving and then changing my main nick to hootle_testing and back to Sam. Whilst as far as users was concerned, both nicks were the same person, stats thought differently. I tried to force a merge by calling the stats API function directly;

 ~ajs dbot.api.stats.mergeStats("aberwiki", "hootle_testing")

Message: TypeError: Cannot convert null to object

But the error message was rather useless, what was null? This could be anything! This route was clearly futile, the API was doing its best to ensure data integrity by not letting whatever error was occurring cause harm to the stored data or the calling function, it was probably returning a null object to represent failure. To provoke an error we'd have to go deeper (statsception?).

I circumvented my own API and tried to invoke the merge functions on the fields myself;

~ajs dbot.db.userStats.aberwiki.sam["#oaosidl"].words.merge(dbot.db.userStats.aberwiki.hootle_testing["#oaosidl"].words)

To no effect. No errors appeared at all. The merge for that particular field had worked, the ~words command (which was still working as it relies on only user object data) was showing my word count had increased by the count stored for hootle_testing. I had a feeling the field at fault was out_mentions whose data property is an empty object initially (as you've mentioned no users). I probed at the data property for the hootle_testing's out_mentions field and the bot issued no reply. It seemed to disagree that there was an object (albeit an empty one) there.

~ajs Object.keys(dbot.db.userStats.aberwiki.hootle_testing["#oaosidl"].out_mentions.data)

In hindsight, I realize that of course there would be no keys inside an empty object and that I should have not been checking with Object.keys. However the worse mistakes was yet to come, when I tried to initialize the data object that I didn't think was there.

~ajs dbot.db.userStats.aberwiki.hootle_testing["#oaosidl"].data = {}

I had forgotten the out_mentions field key completely and instead created a new, empty field called data. My debugging on this occasion was of course a failure, I was unable to find the issue as I'd missed my own mistake. Not realizing I'd added an entirely new field to what was otherwise a perfectly structured although unmergeable user object, I figured I'd come back to the bug in future when more evidence could present itself as to where to look.

This extraneous field easily explains the result from the loop. Of course it failed, the model user object structure had no idea what the "data" field was, thus attempting to access properties such as .toString() that are expected from the model crashes and burns, throwing us out of the loop and out of the onLoad. As it turns out the bot's reloading mechanism elects to quietly add errors to the module's status variable rather than report them on the console. 

~ajs delete(dbot.db.userStats.aberwiki.hootle_testing)

reload stats

All it took was removing the user in question (in fact just the data field would have been sufficient, but there was no need to keep this test user in the database - I don't like inconsistent data!)

But why did it take so long to notice and why was the solution not so obvious even when we knew it was the database at fault?

As explained, the user functionality worked fine, for every single user on the server! Surely if there was incorrect data or corruption, it would at least prevent stats (or even depressionbot itself) from working correctly, and yet all statistics for users were still being incremented, commands that did not require input from channel data (for example ~lines [user] will calculate [user] lines / total channel lines, and thus failed) worked and returned correct results. So initial theories led us to believe there must have been something in the chanStats store preventing those channels from loading and the lack of an onLoad error on the console misled me to believe that the chanStats loading loop must have been executed but was somehow failing to attach the additional functionality to the data fields, rather than actually aborting with an error.

Finally, how did it not affect other users?

As it turns out, hootle_testing was serialized as the last user in the userStats.aberwiki object, not only that but the mistaken "data" data field I had added was the last field to be serialized in the hootle_testing["#oaosidl"] user object, allowing the onLoad loop to successfully load all the additional structure data for all of the user objects on the server including those for hootle_testing before that spurious data field caused a silent assassination of the onLoad before the chanStats loop. Sneaky!

~Sam

[dbotlog]

Stats 101

As you're probably aware, depressionbot stores its "database" in a json encoded flat file and any module which requires some form of storage will make use of this rather simple interface via the bot instance's "db" property. The stats module is no exception and handles data storage via the rather self explanatory database keys; db.userStats and db.chanStats. All of these keys are essentially objects and can contain their own properties; just as userStats and chanStats are properties of db, these two keys house a hierarchical object structure with the actual data stored in leaf properties which are addressed;

dbot.db.userStats.server.user.channel.field

dbot.db.chanStats.server.channel.field

So for example the number of lines I have spoken on aberwiki, in #oaosidl is stored at:

~ajs dbot.db.userStats.aberwiki.sam["#oaosidl"].lines

> 13,789

Unsurprisingly, the total number of lines spoken in #oaosidl itself is stored at:

~ajs dbot.db.chanStats.aberwiki["#oaosidl"].lines

> 50,527

In case you're not versed in the functionality of depressionbot; ~ajs is a command that provides a nick granted administrative privileges a javascript console which works incredibly well as a dbot shell.

As a point of clarification (hopefully); Javascript calls all these keys "properties", when I am speaking specifically about these "leaf" properties that store a metric, I use the term "data fields" or "fields". Also I refer to the objects stored at the userStats.server.user.channel level as "user objects" (so a user will have one of these for each channel they are in) and in turn objects stored at the chanStats.server.channel level as unsurprisingly, "channel objects".

  One of the key questions when planning the data structures for stats was how to easily perform various repetitive actions on the "database" in a generic and extendable manner. For example; whilst the total number of lines you have spoken is a number, stats also records the number of lines you emit per hour, per day in the form of an array and an object keeps track of fellow users you've mentioned, using their nicks as property keys and number of mentions as values. So could there be a way to provide an interface to actions on the data inside these various structures without caring about what the field specifically stores and how it does it?

Not forgetting that Javascript treats these key-value stores as objects, nothing at all stops me from providing a few properties of my own. Could I add properties to a data field to format, fetch, increment and merge the values it stored?

My solution involved the creation of a FieldFactory; a function that could be fed a specification from a user-defined template and return a data field object with these additional functions attached as properties. We can then use this to convert some "dumb" data field into a more aware object, rendering it able to perform particular actions on its own data via these functions in a uniform way. stats ships with two such templates: one for user objects and the other for channel objects.

These templates both house a series of properties; each of which is an object that provides a specification for one particular data field, which in turn houses function definitions for how data should be dealt with for that specific data field. However as you can imagine many of these fields are just relatively simple counts (lines spoken, words spoken, incoming mentions); all formatted, incremented and merged in the exact same way, so surely these templates would simply be full of repeated field function definitions?

Not quite. The FieldFactory is responsible for reading the template's specifications and will attach a suitable default function definition to a data field if an override was not present in the template. For example, the default add method will just increment the field's data (a number) by the amount specified by the passed parameter; perfect for the majority of cases. This ensures templates need only specify functions for fields which differ from a simple counter metric.

Of course, the bot can't save these functions with the data when it is encoded to json for storage as you can't serialize functions of an object itself and even if you could, why would you waste the storage when so many of the functions are the same? The module overcomes this by running the two templates through the FieldFactory, iterating over each field specification, thus creating a model user and model channel object.

Finally, the stats module specifies an onLoad function which dbot will dutifully execute each time the bot is restarted, or if the module itself is reloaded. This onLoad iterates over all the keys in the userStats and chanStats structures, down to the leaves, whereby these model objects are used to copy across the desired functionality for that particular field.

~Sam

[dbotlog]

Admin Access Security Issues

For quite a while depressionbot has had the concept of both moderators and administrators, which have different levels of access to the system - for example moderators can have the bot join/part channels while only admins have the ability to reload the bot or run ~ajs commands. The most common case for setting levels of access is by setting an access level on a particular dbot command. This is done by simply setting the 'access' parameter on a command object to either 'moderator' or 'admin' (the administrators and moderators for the bot being set directly in the bot configuration). Then, as part of the command execution flow in the command module, there is a hasAccess check to see if there are special access considerations for a particular command, and return true only if the user attempting to run the command is of the correct access level. This has proven to be a pretty useful model for securing commands, however it is rather easy to make a mistake and leave a command open for use. For example, it was discovered last night that among all of the commands in the admin command, I had forgotten to set 'admin' access on the 'pushconfig' command, which allows you to modify configuration while the bot is running - this meaning any user could run this command and modify the bot's config. It turns out this is just about the worst admin command that could have been exposed, as a simple 'pushconfig admins myusername' would give you access to all of the other admin commands! This was patched as soon as it was discovered, and since then I have been thinking about curtailing possible future incidences of such oversights. To stop further issues with this in the admin module, in which all commands should require elevated access, I have changed the access setting code so that it first sets all of its commands to require administrator access, and then goes on to redefine those which should require only moderator access. This way, the worst case scenario with forgetting to set an access property in the admin module will mean that a moderator will not be able to run a command they otherwise should be able to. ~reality

[dbotlog]

Now With SSL Support

Thanks to a nice and concise pull request from a new contributor, the elusive John Maguire, JSBot (and DBot by extension) now has support for the use of SSL when connecting to IRC servers. ~reality

[dbotlog]

Introduction to DepressionBot (also, we love DataBank)

I suppose after having been asked repeatedly to write some kind of textual introduction to depressionbot and what exactly we're trying to do with it I'd best relent. We've created this dblog so we can post semi-regular (read: when we can be bothered) updates on how development is going as well as writing up some post-mortems on some hilarious and/or enraging bugs or issues we've had to work around. So depressionbot is an IRC bot built entirely in Node JS, running on JSBot which is a library I developed to interface with the IRC protocol. It's been in development for a little over a year, though true interest only having set things moving at a quick pace in the last couple of months. DBot proper is developed primarily by me, while the excellent Stats module is developed by Sam. Additionally we've received substantial patches from many other contributors (I'd list them all, but I'd have to go and find all their websites to link), By now it includes most features expected of a standard IRC bot, however the aim of the project is to use the versatile nature of Node to provide additional powerful features. The bot has a web interface which, while only being a regular module in the eyes of the bot itself, uses the expressjs library to host a web server which allows any of the other modules in DBot to add functionality to - for example, the quotes module includes an addition to the web interface which allows you to view the quotes on the web. This has already allowed us to create rather rich interfaces, such as the web interface for viewing channel statistics (which is currently missing a few days due to a bug). From this point, we thought why not implement some kind of social network using IRC as the backend, IRC is a nice and federated real-time text-based protocol which is pretty good (when you ignore the fact that no one pays any attention to the RFC anymore). The value of this kind of social network is that because it's just people talking in a room, a large part of the social aspect is already complete and data can be quite naturally gained - the bot is augmenting the already-existing experience. To start this off, we created profiles for users, which include links to relevant statistics and we plan to expand on this with additional fields, 'badges' and all sorts. In the further-off future, we're planning on implementing the ability to use the DBot web interface to be able to chat and perhaps retain a chat session on the IRC server. This means that the whole thing would essentially be a social network in a box which uses plain old IRC channels as a communication backend. Things like games with graphical front-ends could be conducted on the web interface, while all that's actually going on is regular text communication in an IRC channel. Before we can continue with a lot of this stuff, we're working on improving the backend. We're currently implementing the databank library, developed by Canadian Internet Superstar Evan Prodromou - it is a database abstraction library which allows a program to use one of a numerous methods of data storage (nosql, disk, memory etc) while providing a common interface for interaction with the data throughout the software. The intended use for this kind of library is that one might run their entire application with any one of a set of data storage solutions, via an option set in the config file - this being useful for when many instances of a piece of software will be run and there will be differing requirements in terms of data throughput; for example for a personal blog one might choose to store their data in a flat file on the disk without any additional overhead, while a large news website running the same software would probably opt for a NoSQL database. DBot is using Databank in a slightly alternative manner, in providing individual modules the option as to which method of data storage they wish to use. Up until now, we were storing all data in a big object and occasionally serialising this to a 'db.json' file (lazy, yes, yes) - this actually wasn't a problem for a long time, until Sam started developing his audacious statistics plugin which brings with it an obscene amount of data throughput in the application. Obviously this meant that we needed something like Redis to conduct the statistics module's data storage with. The problem was that it seemed wasteful to set up a Redis server within the module - perhaps some other module in the future would need this kind of support. So Databank allows us to retain centralised data storage in DBot, while allowing for a number of different storage options as well as providing a common interface to data storage within depressionbot. This means we can use Redis for Stats, while the module which tracks who has ignores set on which modules can continue using disk-based storage without additional overhead or any other such problems. This also has the benefit of not having to add dependencies for the entire application if only certain modules use that functionality - i.e. Redis will be a dependency of Stats, rather than DBot. We hope to finish the Databank implementation very soon, release 0.4 and continue development on everything we have in plan for the future! ~reality