The Chainsaw Infanticide Logger Manuever

[Zed A. Shaw]

One of the things that's really great about agile languages is they give you the power to do anything. One of the most horrible things about agile languages is they give every other idiot the same power to stab you in the back with a rusty pitchfork.

I needed to do some simple logging. I made a Logger class and started writing to it. Hmm, my log messages sometimes have a format and sometimes they don't. Nothing I do fixes this.

Three hours later and half my sanity, I start to snoop through the libraries I've included, and I find this wonderfully horrible gem:

http://rafb.net/paste/results/0vADxJ56.html

Not only does this code re-open a class to do something that could *just as easily be done with subclassing*, but the author also TURNS OFF DOCUMENTATION with :nodoc: so that nobody knows about it. Great! So much for Principle Of Least Surprise. This is more like Principle Of Most Heinous Arsenic Injection.

I then trolled through a few more projects and found that this is common practice. The glue project does it. Glue even goes so far as to re-open the Logger class *just so it can turn it into a singleton*. Great Buddha the insanity is everywhere!

http://rafb.net/paste/results/yXNJvv50.html

What's wrong with you people? This is the absolute worst thing I've ever experienced in any language I've used. I thought having magic AspectJ crap silently move my code was bad. At least that stuff was documented and I could optionally turn it off. This can only be fixed with leprechaun backflips into a pool of jello while covered in chocolate. Translation: it can't be fixed easily and I shouldn't have to "fix" it since I didn't break it.

-- Please, think of the children before you re-open their parent with a damn chainsaw. --

I only re-open a class after I've tried every other option like subclassing, wrapping, etc. If nothing else works or is too much effort for the modification, then I DOCUMENT THE HELL out of my modification and try desperately to localize the change so that it doesn't hurt anyone else.

Alright, rant off. Please stop doing this. My appologies if I hurt anyone's feelings.

Zed A. Shaw
http://www.zedshaw.com/

 

[Gavin Kistner]

On Aug 23, 2005, at 10:06 PM, Zed A. Shaw wrote:
[... snip an awesome tirade...]

ROFLMAO. Well written

"Principle Of Most Heinous Arsenic Injection"...*giggle*

Thanks for the laugh. I agree with your sentiments, and the way
you've written them.

 

[James Britt]

Zed A. Shaw wrote:
...

Alright, rant off. Please stop doing this. My appologies if I hurt anyone's feelings.

I take it you first tried to contact the author of the offending code
before ranting in public?

James


--

http://www.ruby-doc.org - The Ruby Documentation Site
http://www.rubyxml.com - News, Articles, and Listings for Ruby & XML
http://www.rubystuff.com - The Ruby Store for Ruby Stuff
http://www.jamesbritt.com - Playing with Better Toys

 

[Nicholas Seckar]

Zedas, here's concept as discussed in #ruby-lang... Take note that I've
reopened Logger.

class Logger
# Dictate the way in which this logger should format the messages
# it displays. This method requires a block. The block should return
# formatted strings given severity, timestamp, msg, progname.
#
# Useless example:
#
# logger = Logger.new
# logger.format do |severity, timestamp, msg, progname|
# "#{progname}@#{timestamp} - #{severity}::#{msg}"
# end
#
def format(&format_proc)
raise 'feed me a block dude' unless format_proc
@format_proc = format_proc
end

# hackish use of *args, give me some love
def format_message(*args)
@format_proc ? @format_proc.call(*args) : super(*args)
end
end

 

[Eric Hodel]

One of the things that's really great about agile languages is they
give you the power to do anything. One of the most horrible things
about agile languages is they give every other idiot the same power
to stab you in the back with a rusty pitchfork.

I needed to do some simple logging. I made a Logger class and
started writing to it. Hmm, my log messages sometimes have a
format and sometimes they don't. Nothing I do fixes this.

Three hours later and half my sanity, I start to snoop through the
libraries I've included, and I find this wonderfully horrible gem:

http://rafb.net/paste/results/0vADxJ56.html

Oh? You think that's bad?

There's also this gem sitting right next to it.

def silence_warnings
old_verbose, $VERBOSE = $VERBOSE, nil
begin
yield
ensure
$VERBOSE = old_verbose
end
end

So that things like this can be done:

silence_warnings { Customer = Struct.new("Customer", :name) }

instead of doing something simple like:

unless defined? Customer
Customer = Struct.new "Customer", :name
end

 

[David Brady]

Guys,

I don't understand. This is a feature of agile languages, not a
defect. Leaving the door open for chainsaw-wielding maniacs also leaves
the door open for gifted neurosurgeons.

I understand your frustration, and I feel your pain. But I am left with
a critical question:

Where were your unit tests?

Admittedly, silence_warnings might not be testable. You might have to
code review that to catch it. But then again, if *your* unit tests all
pass, then silence_warnings shouldn't affect you--especially if you test
the failure cases and assert that warnings were returned. Logger
integrity, however, should be straightforward.

I don't mean to come across like a heartless jerk or a TDD zealot. I am
neither. I am just looking at your pain and thinking, "why does this
have to hurt?"

-dB

 

[Bill Kelly]

I then trolled through a few more projects and found that this
is common practice. The glue project does it. Glue even goes
so far as to re-open the Logger class *just so it can turn it
into a singleton*. Great Buddha the insanity is everywhere!

I was bitten recently by a change to the CGI module. I don't
think I can get to quite the same level of moral outrage on this
one because by comparison what I ran afoul of seems more like what
one would expect to be a legitimate leveraging of the Power of Ruby,
even in a library context: no global classes or constants were
being opened or modified. Something that I used to convert to a
String instance, was now still a String, but its singleton class had
been extended with additional features. Including some accompanying
instance variables, which is the part that bit me.

My code was littered with cgi['some_parameter'].to_s
because I'd long ago learned that CGI returned something as
a parameter value that acted like a String, but wasn't really.
I added the .to_s when fetching CGI parameters, because the values
I fetch eventually end up in objects which are serialized out to
a flat-file database with YAML.

A recent change to CGI that was--probably--for most intents and
purposes at least as good or better than the way it used to work
was apparently to make cgi['some_parameter'] now return a genuine
String - but one that had been extended with extra features.
Unfortunately, this had the effect of turning my .to_s calls into
no-op's. This had the ultimately semi-harmless but alarming and
baffling result of my database files beginning to show signs of
very strange bloat: objects that used to appear as simple strings
in the YAML, were now complex dumps of objects that included the
string value, but also these ancillary CGI parameters that were
hitchhiking on these extended String objects CGI was now returning
as parameter values.

I think it took me at least an hour and a half to track down the
cause. (Seemed like an eternity because I was working under a
deadline.)

To fix it, I did decide to open the String class with, well maybe
a small set of electric hedge trimmers. But I'm only dealing with
my private application here. If it were a library I were writing,
I'd go to prodigious lengths to try to not modify the global behavior
of Ruby. My cheesy application-level fix:

class String
# %%BWK -- this is a kludge to work around the CGI module extending
# String objects fetched from its parameters with some
# extra instance variables, which cause really verbose YAML
# to be output.
# I already was doing to_s on everything I fetched from
# the CGI parameters, thinking that was enough to give me
# a String without any extra baggage. This kludge forces
# my assumption to be a true one.
def to_s
String.new(self)
end
end

I'm not entirely sure what point I'm driving toward - because
really what CGI is doing seems to me in general like a pretty
reasonable use of Ruby. . . And yet it _bit_ me in a similar way to
what you reported about the Logger Maneuver.

I guess in general, Library Authors Take Note: Getting tricky in
your library can end up playing a trick on your users.


Regards,

Bill

 

[Jeff Wood]

My feelings are in-line with the review of Dave's session as OSCON @

http://raibledesigns.com/page/rd?entry=3Doscon_monday_morning

---QUOTE---

Classes are open: in Ruby, you can always add methods, attributes,
etc. to existing classes. For example, you can add an encrypt() method
to the String class. Isn't this dangerous? What if someone changes the
logic of + for math expressions. No, because if one of your
programmers overrides methods that breaks things - you take them out
in the parking lot and beat them with a rubber hose! The language
shouldn't prohibit us from doing powerful things.

---END QUOTE---

You shouldn't be afraid of having power. That's why you have tests.
You do have tests, right? ... right??? ... RIGHT !!?!?!?!??!

j.

I then trolled through a few more projects and found that this
is common practice. The glue project does it. Glue even goes
so far as to re-open the Logger class *just so it can turn it
into a singleton*. Great Buddha the insanity is everywhere!

=20
I was bitten recently by a change to the CGI module. I don't
think I can get to quite the same level of moral outrage on this
one because by comparison what I ran afoul of seems more like what
one would expect to be a legitimate leveraging of the Power of Ruby,
even in a library context: no global classes or constants were
being opened or modified. Something that I used to convert to a
String instance, was now still a String, but its singleton class had
been extended with additional features. Including some accompanying
instance variables, which is the part that bit me.
=20
My code was littered with cgi['some_parameter'].to_s
because I'd long ago learned that CGI returned something as
a parameter value that acted like a String, but wasn't really.
I added the .to_s when fetching CGI parameters, because the values
I fetch eventually end up in objects which are serialized out to
a flat-file database with YAML.
=20
A recent change to CGI that was--probably--for most intents and
purposes at least as good or better than the way it used to work
was apparently to make cgi['some_parameter'] now return a genuine
String - but one that had been extended with extra features.
Unfortunately, this had the effect of turning my .to_s calls into
no-op's. This had the ultimately semi-harmless but alarming and
baffling result of my database files beginning to show signs of
very strange bloat: objects that used to appear as simple strings
in the YAML, were now complex dumps of objects that included the
string value, but also these ancillary CGI parameters that were
hitchhiking on these extended String objects CGI was now returning
as parameter values.
=20
I think it took me at least an hour and a half to track down the
cause. (Seemed like an eternity because I was working under a
deadline.)
=20
To fix it, I did decide to open the String class with, well maybe
a small set of electric hedge trimmers. But I'm only dealing with
my private application here. If it were a library I were writing,
I'd go to prodigious lengths to try to not modify the global behavior
of Ruby. My cheesy application-level fix:
=20
class String
# %%BWK -- this is a kludge to work around the CGI module extending
# String objects fetched from its parameters with some
# extra instance variables, which cause really verbose YAML
# to be output.
# I already was doing to_s on everything I fetched from
# the CGI parameters, thinking that was enough to give me
# a String without any extra baggage. This kludge forces
# my assumption to be a true one.
def to_s
String.new(self)
end
end
=20
I'm not entirely sure what point I'm driving toward - because
really what CGI is doing seems to me in general like a pretty
reasonable use of Ruby. . . And yet it _bit_ me in a similar way to
what you reported about the Logger Maneuver.
=20
I guess in general, Library Authors Take Note: Getting tricky in
your library can end up playing a trick on your users.
=20
=20
Regards,
=20
Bill
=20
=20
=20
=20

--=20
"So long, and thanks for all the fish"

Jeff Wood

 

[Bill Kelly]

You shouldn't be afraid of having power. That's why you have tests.
You do have tests, right? ... right??? ... RIGHT !!?!?!?!??!

Dudes, I do have tests. How in blazes would you write a test
to catch the problem I described? (Please show your work.
And why would you ever think to do so?

It's not being afraid of having power. In my own applications,
I'll exploit any and every cool capability of Ruby I feel like.

But when I personally write a module I view as a library I'd
like others to find useful, I take a decidedly more conservative
approach - deliberately.

Do you not consider libraries and applications different, where
Ruby's beloved Openness is concerned?


Regards,

Bill

 

[Jeff Wood]

The truely iterative & testing-complete way to build software is to
design and implement your tests before you write your code. When all
of your tests pass, you're done...

... If you built your system like that, you should have tests for each
and every action on your classes ... and the first time somebody elses
modifications has an affect on your functionality and expected output,
you should know about it.

j.

=20
Dudes, I do have tests. How in blazes would you write a test
to catch the problem I described? (Please show your work.
And why would you ever think to do so?
=20
It's not being afraid of having power. In my own applications,
I'll exploit any and every cool capability of Ruby I feel like.
=20
But when I personally write a module I view as a library I'd
like others to find useful, I take a decidedly more conservative
approach - deliberately.
=20
Do you not consider libraries and applications different, where
Ruby's beloved Openness is concerned?
=20
=20
Regards,
=20
Bill
=20
=20
=20
=20

--=20
"So long, and thanks for all the fish"

Jeff Wood

 

[Jeff Wood]

So,=20

To answer "how/why would you test this"... you should have tests in
place for your logging functionality. The second something doesn't
come out right, you know that something is marring the system.=20
Debugging starts by walking the source of the packages you are using
and watching for references to the modified functionality... It's not
that hard to track down.

Anyways, that's what I do ... it works for me. As far as posting
example code ... sorry, some companies don't let ya do that.

j.

=20
Dudes, I do have tests. How in blazes would you write a test
to catch the problem I described? (Please show your work.
And why would you ever think to do so?
=20
It's not being afraid of having power. In my own applications,
I'll exploit any and every cool capability of Ruby I feel like.
=20
But when I personally write a module I view as a library I'd
like others to find useful, I take a decidedly more conservative
approach - deliberately.
=20
Do you not consider libraries and applications different, where
Ruby's beloved Openness is concerned?
=20
=20
Regards,
=20
Bill
=20
=20
=20
=20

--=20
"So long, and thanks for all the fish"

Jeff Wood

 

[Austin Ziegler]

You shouldn't be afraid of having power. That's why you have tests.
You do have tests, right? ... right??? ... RIGHT !!?!?!?!??!

I think the real problem is when this is done in released code. If
you're going to extend code, extend it cleanly -- IMO.

-austin
--=20
Austin Ziegler * (e-mail address removed)
* Alternate: (e-mail address removed)

 

[Daniel Berger]

So,

To answer "how/why would you test this"... you should have tests in
place for your logging functionality. The second something doesn't
come out right, you know that something is marring the system.
Debugging starts by walking the source of the packages you are using
and watching for references to the modified functionality... It's not
that hard to track down.

As Alexander mentioned, the point of the email was not that he couldn't detect
it, it's that there's nothing he can do about it short of extending the Logger
class *again* to make it do what he wants.

Unit tests detect the problem, they don't solve it. Since the OP controls
neither the logger package nor the glue package, his choices are limited.

Plus, I'll second Alexander's assertion that you should never have to include
unit tests to verify that classes work as advertised. That's the package
author's job, and a programmer's job not to screw with their behavior,
especially not classes in core and/or stdlib. The alternative is a horribly
slippery slope.

Regards,

Dan

 

[Nikolai Weibull]

---QUOTE---

Classes are open: in Ruby, you can always add methods, attributes,
etc. to existing classes. For example, you can add an encrypt() method
to the String class. Isn't this dangerous? What if someone changes the
logic of + for math expressions. No, because if one of your
programmers overrides methods that breaks things - you take them out
in the parking lot and beat them with a rubber hose! The language
shouldn't prohibit us from doing powerful things.

---END QUOTE---

Violence is surely the road to enlightenment,
nikolai

 

[Jeff Wood]

Ok, my set of tests for my application would include asserting that if
a given piece of functionality is going to cause a log message to
occur, that I validate the residual log files do contain the log
entries I expected as I expected them to be formatted. If they don't=20
then the application/library doesn't meet it's spec and/or
requirements. It's a bug and it needs to be resolved.

So, you would then have a front-row seat if something was affecting
the logger output.

And no, I don't believe there is any difference between building a
library and building an application ... it's all code that needs to be
tested and made sure it functions completely as designed.

I hope that answers you sufficiently.

j.

Jeff,
=20

=20
I appreciate the well-meaning nature of your replies, but I've
been programming for 24 years and doing TDD semi-consistently
for the last 5.
=20
Again, I'd ask to see what sort of test you'd propose that would
catch the problem I described. (My post, the one you quoted, was
about CGI, not the Logger.)
=20
=20
Thanks for the tip. =3DD
=20
=20
I also would ask again, Do you not consider libraries and applications
different, where Ruby's beloved Openness is concerned?
=20
=20
Regards,
=20
Bill
=20
=20
=20
=20

--=20
"So long, and thanks for all the fish"

Jeff Wood

 

[Eric Hodel]

Guys,

I don't understand. This is a feature of agile languages, not a
defect. Leaving the door open for chainsaw-wielding maniacs also
leaves the door open for gifted neurosurgeons.

I understand your frustration, and I feel your pain. But I am left
with a critical question:

Where were your unit tests?

I don't understand why I'm supposed to test a standard library I'm
using. Usually I read the documentation and expect it to work that
way, but maybe I'm crazy.

Admittedly, silence_warnings might not be testable. You might have
to code review that to catch it. But then again, if *your* unit
tests all pass, then silence_warnings shouldn't affect you--
especially if you test the failure cases and assert that warnings
were returned.

Right now, silence_warnings is only used in the library's test code,
but that doesn't mean it won't get abused and start wrapping things
that *should* give warnings. (Of course, the library in question is
so completely -w unsafe, the warnings would be lost in a pages of
noise.)

The way silence_warnings is used is the real problem. Ruby already
has a perfectly good method of doing exactly what silence_warnings
was written to accomplish (two of them, in fact!).

Logger integrity, however, should be straightforward.

You would think that, until one library decides to go ahead and break
it. The library where these were found has at least a handful of
places where you can find questionable software engineering practices.

I don't mean to come across like a heartless jerk or a TDD zealot.
I am neither. I am just looking at your pain and thinking, "why
does this have to hurt?"

It hurts because the library decided to us in the middle of a
minefield without a map.

 

[David Brady]

Again, I'd ask to see what sort of test you'd propose that would
catch the problem I described. (My post, the one you quoted, was
about CGI, not the Logger.)

I find that the hardest tests to write are the ones that I overlooked
because I am unaware of my blind spots.

Until I read your post, I thought like you did--that to_s flattened an
object into a chunk of text. But now I see that it doesn't. It doesn't
even return a String object! It returns an object that behaves--dare I
say quacks?--like a String.

Another assumption you may be making--and once I state it, the test for
it should become obvious--is that YAML should output pleasingly human
readable text, even if it loses the ability to correctly restore objects.

I know, I know. There exists in business the concept of "approprately
incorrect". You are using YAML to produce "appropriately incorrect" files.

The behavior you want is "take a Stringlike object, and emit pleasingly
simplified text". That's easily testable. Take your CGI object, have
YAML dump it, then open the YAML file manually and see that the text is
correct. Or build a CGI object, then build an equivalent object using
Strings, output them to different files and then assert that there is no
difference between the files. The second method may seem more robust,
because it lets you not care how YAML stores Strings... but that's the
rabbit that led us down this hole in the first place. Use the first
method, because you don't care if YAML stores CGI the same as a String,
you care that the output is pleasing to read. If YAML changes the way
it stores String, you'll want this test to break. Your app should
shriek until you have verified that the new format is pleasant.

Once you have a regression test in place, you will be able to remove the
hack to String#to_s and know when your application is fixed. A good
alternative to your hack, perhaps, is to replace YAML with a dumper of
your own devising that transforms Stringlike-->String on save/reload.
Perhaps even a child class of YAML, whose only override is something like:

obj = String.new(obj) if obj.respond_to? :to_str && obj.class != String

I haven't learned how to see my blind spots yet. I could not have
prevented this bug from happening. But having happened, I can
immediately write a test that verifies that it is fixed, and that future
revisions to CGI, YAML, and even String will be regression tested
against this bug.

Cheers,

-dB

 

[David Brady]

I don't understand why I'm supposed to test a standard library I'm
using. Usually I read the documentation and expect it to work that
way, but maybe I'm crazy.

Me either. I thought Logger was your own code. I agree that you
shouldn't have to unit test a library that you trust.

If it's just Logger that's crap, then you can shrug and decide not to
trust the library and respond accordingly. But you're right, that Ruby
allows other programmers to open a library you trust and bash it into
untrustworthiness. That's a real problem that should be considered.

Is the following legal unit test code?

def test_no_messing_with_trusted_libraries
require 'logger'
Logger.freeze
assert_nothing_raised( require 'suspect_module', "Hey! Somebody's
mucking with the logger module!" )
end

You're right, you shouldn't HAVE to run that test.

-dB

 

[Jeff Wood]

I'm not saying you need to test Logger ... I'm simply stating that you
should be asserting ALL of the behaviors you design into your
application.

What if logger isn't even being called ??? or any of a number of
situations like that... Simply verifying that the application behaves
in all ways as designed/required isn't "testing Logger".

j.

Eric Hodel wrote:
=20
=20
Me either. I thought Logger was your own code. I agree that you
shouldn't have to unit test a library that you trust.
=20
If it's just Logger that's crap, then you can shrug and decide not to
trust the library and respond accordingly. But you're right, that Ruby
allows other programmers to open a library you trust and bash it into
untrustworthiness. That's a real problem that should be considered.
=20
Is the following legal unit test code?
=20
def test_no_messing_with_trusted_libraries
require 'logger'
Logger.freeze
assert_nothing_raised( require 'suspect_module', "Hey! Somebody's
mucking with the logger module!" )
end
=20
You're right, you shouldn't HAVE to run that test.
=20
-dB
=20
--
David Brady
(e-mail address removed)
I'm feeling really surreal today... OR AM I?
=20
=20
=20

--=20
"So long, and thanks for all the fish"

Jeff Wood

 

[Bill Kelly]

Hi David,

Thanks for your thoughtful reply.

I find that the hardest tests to write are the ones that I overlooked
because I am unaware of my blind spots.

Yes - agreed.

Until I read your post, I thought like you did--that to_s flattened an
object into a chunk of text. But now I see that it doesn't. It doesn't
even return a String object! It returns an object that behaves--dare I
say quacks?--like a String.

Another assumption you may be making--and once I state it, the test for
it should become obvious--is that YAML should output pleasingly human
readable text, even if it loses the ability to correctly restore objects.

Hmm... Actually my assumption (or hope) would be that YAML always
be able to write out objects that it can correctly restore. My
reason for wanting my application to be serializing "real" simple
strings isn't really tied, I think, to any assumptions about how
YAML itself should behave.

But yes, I want my *application* to, using YAML, output simple
strings that are not only pleasingly human readable, but also
compact*. I have no problem with YAML doing exactly what I've
asked it to. I just didn't realize I was feeding it complex
singleton String instances with "extra" instance variables.

(*) The compactness is desirable for performance reasons:
I'm already splitting my databases via hashing into 4093 sub-
files, so each component file of the database can be loaded/saved
quickly enough. YAML Ain't Mercurial Lightning... ?

I know, I know. There exists in business the concept of "approprately
incorrect". You are using YAML to produce "appropriately incorrect" files.

I'm not sure I agree. I'm using YAML to accurately serialize my
data. It's my fault for feeding it unexpectedly complex data.

The behavior you want is "take a Stringlike object, and emit pleasingly
simplified text". That's easily testable. Take your CGI object, have
YAML dump it, then open the YAML file manually and see that the text is
correct. Or build a CGI object, then build an equivalent object using
Strings, output them to different files and then assert that there is no
difference between the files. The second method may seem more robust,
because it lets you not care how YAML stores Strings... but that's the
rabbit that led us down this hole in the first place. Use the first
method, because you don't care if YAML stores CGI the same as a String,
you care that the output is pleasing to read. If YAML changes the way
it stores String, you'll want this test to break. Your app should
shriek until you have verified that the new format is pleasant.

One test I had in mind was,

assert( cgi['something'].to_s.to_yaml ==
String.new(cgi['something'].to_s).to_yaml )

...but that test does rely on my modified String#to_s behavior.

One complication is that, for the time being, my application needs
to run on systems with the 1.8.1 CGI behavior (which returns a
parameter value as a non-String-object that quacks like a String),
and the 1.8.2 CGI behavior (which returns a paramater value as a
genuine String instance whose singleton class happens to have been
extend'ed with a module that includes some bonus instance variables.)

So far, my String#to_s hack still seems like a reasonable enough
way to enforce the behavior I need in my current application. (But
again, I'd NOT take this hack approach if I were writing a library.)

So, given my String#to_s hack, I think the above assert() should
cover the specific problem I was having.

A more direct approach might have been for me to open the CGI class
and replace CGI#[] so that it returned simple String instances, not
complex extend'ed ones. (Again, something I'd consider for my app,
but not for a library.)

I'm not sure if more general tests involving YAML and Strings would
help, since I don't *really* want to change YAML's behavior - I just
want to not accidentally feed it complex objects.


Regards,

Bill