Logging … and how not to do it.

One thing that really annoys me is when I come to look at the log file and I see something like :

blah blah did blah blah
blah foo blah random comment
fish blah some data
which spans many lines or does it?

This is bad, as I’ve got absolutely no idea where the messages are from (so have to grep around a code base), and I’ve no idea WHEN they were made. At best I can look at timestamps on this file and figure out a timeframe (assuming logrotate is in use so there is a definite (must be after X timestamp)).

What’s far better from a maintenance point of view :

2010/07/29 09:33 filewhatever.py:355 blah blah blah did blah blah

2010/07/29 09:34 filewhatever.py:355 blah blah blah did blah blah

2010/07/29 09:35 filewhatever.py:355 data received from x is {{{hello world…. }}}

Changes are :

  1. Date and time stamps (in python: datetime.datetime.now())
  2. Recording where the message came from (see the ‘inspect’ python module – inspect.stack()[1][1] for calling file, and inspect.stack()[1][2] for the line number, or debug_backtrace() in PHP)
  3. Wrapping any interesting output (e.g. from a remote service) in obvious delimiters (e.g. {{{ and }}} )  – without e.g. timestamps or some other common line prefix, I’ve no way of knowing what’s from where, especially if the output spreads over many lines.

Other good ideas :

  1. Different severities of log message (classic: debug, info, error type annotation with appropriate filtering).
  2. Make sure logrotate is in use, or a simple shell script via cron, to stop the log file growing too large and causing problems.
  3. Stop writing your own logging mechanisms and use ones provided by the system (e.g. Python has a logger built in which does all of the above and more)

EOR – EndOfRant

Twitter Weekly Updates for 2010-07-25

  • Morrisons. You are the worst supermarket ever. Let me buy single bananas. #
  • Even with an iPhone and google maps etc I got lost around Bentley / webheath. #amireallyawoman #mapreadingfail #
  • Cycled to arrow valley park (redditch) and back, via lickey hill (out) and cycle route 5 on the way back….. #
  • Cycling with a dead weight toddler in a rear seat is hard. This might have to become a regular routine. #
  • Toddler cycling day (well I'm cycling, he's along for the ride) #
  • Hmm. Apple case app crashed my phone. Great. Shame there aren't more pictures or info provided to help me choose #iPhone4 #case #
  • Wish subversion would let me revert line ranges within a file so I can easily avoid committing whitespace changes etc. #svn #
  • FOOL WOMEN into thinking their opinions are valued by nodding occasionally and saying 'mmm' /via @VizTopTips #
  • Say the word and I'll be gone. Say the word and I'll be gone forever, and ever. #
  • Yey. Query time reduced from 2.5 seconds to 0 seconds. And a happy customer soon. #
  • http://www.myconfinedspace.com/2010/07/20/proper-use-of-your-and-there/ #

Twitter Weekly Updates for 2010-07-25

  • Morrisons. You are the worst supermarket ever. Let me buy single bananas. #
  • Even with an iPhone and google maps etc I got lost around Bentley / webheath. #amireallyawoman #mapreadingfail #
  • Cycled to arrow valley park (redditch) and back, via lickey hill (out) and cycle route 5 on the way back….. #
  • Cycling with a dead weight toddler in a rear seat is hard. This might have to become a regular routine. #
  • Toddler cycling day (well I'm cycling, he's along for the ride) #
  • Hmm. Apple case app crashed my phone. Great. Shame there aren't more pictures or info provided to help me choose #iPhone4 #case #
  • Wish subversion would let me revert line ranges within a file so I can easily avoid committing whitespace changes etc. #svn #
  • FOOL WOMEN into thinking their opinions are valued by nodding occasionally and saying 'mmm' /via @VizTopTips #
  • Say the word and I'll be gone. Say the word and I'll be gone forever, and ever. #
  • Yey. Query time reduced from 2.5 seconds to 0 seconds. And a happy customer soon. #
  • http://www.myconfinedspace.com/2010/07/20/proper-use-of-your-and-there/ #

Twitter Weekly Updates for 2010-07-18

  • Good morning world. #
  • . @ChairmumMiaow is on @BBcWm tomorrow
    Morning (fri) to talk about upcoming breastfeeding picnic (Monday – http://bit.ly/brumbfpicnic) #
  • Breastfeeding picnic in Birmingham – monday 19th July 12-3pm http://bit.ly/brumbfpicnic see fb group. #Birmingham #bfpicnic #
  • Sblug html5 talk from @brucel might start soon. #
  • So much for an early night. Potential office viewing tomorrow…. *crosses fingers* #
  • Evolution is better than thunderbird for mail on Linux …. Except for address learning / completion. #
  • Interesting day – customer turns up unannounced for what turns into a near 5 hour meeting. Still he bought lunch 🙂 #
  • Finding a wordpress virus thing (eval(gzinflate(base64_decode(….)))) on a site just before bed is annoying. Timestamp implies before us 🙂 #
  • 2 old ladies sitting in church 1 leans over and whispers to the other "my butt is going to sleep", other replies "i heard it snore 3 times" #
  • I love orange. O2 you sucked so much. #
  • Sweet. FETIDUS is back on podcast. Zombies. Yey. #
  • I'm not sorry to see the Food Standards Agency go 🙂 #fsa #
  • Thanks mr postman for parking your bike right in front of me in the middle of the fricking pavement. #
  • This is excellent and should be seen by everyone: http://is.gd/doq8o /via @FellowAtheists – zombies religion venn diagram #
  • My 10km time – 42.38 (43rd, last year: 42.50 & 29th). #timberhonger #running #bromsgrove (results at http://timberhonger10k.co.uk) #
  • Back home from the launch party of Intimate Perfection. Go Jenny! Congrats on doing the England team! And the world cup winners get it free? #

Twitter Weekly Updates for 2010-07-11

  • BBQ time ! #
  • Timberhonger 10k race tomorrow; here's to hoping my legs are up to it. #bromsgrove #10km #run #
  • A woman says she's uncomfortable watching you wank. You A: need more time together B: she's a prude C: Tell her to sit elsewhere on the bus. #
  • I`m getting sick of these Tyneside gunman jokes. They`re not even raoulmoatly funny. #
  • Postfixadmin 2.3.1 live; .rpms and .debs etc; see http://postfixadmin.sf.net – virtual mail domain admin tool for postfix #php #mail #isp #
  • Turned on the radio to kerrang. Toddler demanded we danced. Fun times. Shame the radio reverted to talking after the song. #
  • Ooh. Thanks John truslove. Two potential offices to view 🙂 bromsgrove ftw 😉 #
  • Bromsgrove … Where are the decent offices hidden.? Room for 4-5 required. #
  • Postfixadmin release 2.3.1 is almost here. #postfix #linux #sysadmin #
  • Paddy tells Mick he`s thinkin of buying a labrador. "F___ off" says Mick, "have you seen how many of their owners go blind?" #joke #
  • Women! They just don't have a sense of humour. The wife didn`t find it nearly as funny as I, when I replaced her tampon with a party popper! #
  • OH: "website ______ is crap it has BNP images in it…. " (I heard bnp, he did say bmp). #
  • I quite like my jabphone 4 but cant help think it's a bit like the emperors new clothes. Wish orange would port my number too. #iphone4 #
  • The estate has a scrap man who drives around in an ex-BT transit van. Failure on so many levels, and let's not mention his 'jingle' #
  • Sweet. Phone didn't loose 3G coverage walking home. Suck on that o2, orange ftw. #
  • Come on orange. Finish porting my number. #
  • Twitterific on my new phone seems to be having a bad day wrt authentication #
  • RT @CalEvans: http://bit.ly/a4MLMx #rofl Rasmus has the patience of Job. #php /via @akrabat #

Twitter Weekly Updates for 2010-07-11

  • BBQ time ! #
  • Timberhonger 10k race tomorrow; here's to hoping my legs are up to it. #bromsgrove #10km #run #
  • A woman says she's uncomfortable watching you wank. You A: need more time together B: she's a prude C: Tell her to sit elsewhere on the bus. #
  • I`m getting sick of these Tyneside gunman jokes. They`re not even raoulmoatly funny. #
  • Postfixadmin 2.3.1 live; .rpms and .debs etc; see http://postfixadmin.sf.net – virtual mail domain admin tool for postfix #php #mail #isp #
  • Turned on the radio to kerrang. Toddler demanded we danced. Fun times. Shame the radio reverted to talking after the song. #
  • Ooh. Thanks John truslove. Two potential offices to view 🙂 bromsgrove ftw 😉 #
  • Bromsgrove … Where are the decent offices hidden.? Room for 4-5 required. #
  • Postfixadmin release 2.3.1 is almost here. #postfix #linux #sysadmin #
  • Paddy tells Mick he`s thinkin of buying a labrador. "F___ off" says Mick, "have you seen how many of their owners go blind?" #joke #
  • Women! They just don't have a sense of humour. The wife didn`t find it nearly as funny as I, when I replaced her tampon with a party popper! #
  • OH: "website ______ is crap it has BNP images in it…. " (I heard bnp, he did say bmp). #
  • I quite like my jabphone 4 but cant help think it's a bit like the emperors new clothes. Wish orange would port my number too. #iphone4 #
  • The estate has a scrap man who drives around in an ex-BT transit van. Failure on so many levels, and let's not mention his 'jingle' #
  • Sweet. Phone didn't loose 3G coverage walking home. Suck on that o2, orange ftw. #
  • Come on orange. Finish porting my number. #
  • Twitterific on my new phone seems to be having a bad day wrt authentication #
  • RT @CalEvans: http://bit.ly/a4MLMx #rofl Rasmus has the patience of Job. #php /via @akrabat #

Adventures in Continuous Integration (PHP, Xinc, Phing etc)

I’ve had cron’ed unit tests running for ages which happily spam me when stuff breaks – and likewise adding e.g. phpdoc generation and so on into the mix wouldn’t be too hard.

Anyway, for want of something better to do with my time I thought I’d look into CI in a bit more depth for one customer’s project. As some background, we’ve maintained their software for about the last 12-18 months, the project is largely procedural – although we’re introducing Propel, Zend Framework, Smarty etc into the mix slowly over time. We’ve also added a number of unit tests to try and keep some of the pain points in the project under control.

So, there’s the background.

With regards to CI within a PHP environment there seem to be three options:

  1. phpUnderControl
  2. Xinc
  3. Hudson

To the best of my knowledge 1 & 3 require Tomcat, and therefore are Java based. I thought I’d try and make my life easy and stick with Xinc which is written in PHP (and perhaps therefore something I can hack/patch/modify if needs be).

In retrospect I’m questioning whether I made the right choice – Xinc seems to be unmaintained and unloved at the moment.

Xinc Installation

It should be the case of doing something easy like :

pear channel-discover pear.xinc.eu
pear install xinc/xinc

Unfortunately, the Xinc project seems a little unloved as of late, and it’s necessary to use an unofficial mirror :
pear channel-discover pear.ctrl-zetta.com
pear install ctrl-zetta/Xinc

(This required rummaging through Xinc’s issue log… *sigh*).

Follow the instructions and it’s not really difficult to install. There’s no requirement for a database or anything.

Once installed, edit /etc/xinc/config.xml and comment out the <project>…</project> block and instead only edit /etc/xinc/conf.d/whatever.xml – in my case I just copied the skeleton one and added in stuff… giving something like the following project.xml

In a nutshell, this says:

  1. Run from /var/www/xinc/whatever.test.palepurple.co.uk
  2. Every 900 seconds rebuild using what’s defined in the <builders> tag
  3. Always build (hence <buildalways/>) – in reality, you’d probably want the <svn directory=${dir}” update=”true”/> enabled so rebuilds only occur if someone’s changed svn.
  4. Once the build is complete, publish the php docs (found in ${dir}/apidocs)
  5. Once the build is complete report the results of the unit tests using ${dir}/report/logfile.xml – obviously this path needs to match up with what’s in your phing build.xml file.
  6. If a build fails, email root
  7. If a build succeeds after a failure, email root
  8. When a build succeeds, run the publish.xml file through phing (target: build) – this is used to create a .tar.gz with appropriate numbering which appears within Xinc’s web ui for download.

Obviously in my case, this didn’t get me very far initially as the project wasn’t using phing.. so that was task #2.

Phing

I had a few issues once I started to phing-ise things – firstly, I’ve always historically used SimpleTest as my unit test framework of choice – unfortunately it’s phing and Xinc integration isn’t all that good – and phpUnit is clearly superior in this respect. So I quickly converted out tests from SimpleTest to phpUnit – thankfully this wasn’t too hard as all my tests extent a local class (LocalTest) (hence the exclude line in the build.xml file below) to which I just added a few aliasing methods in so all the PhpUnit/SimpleTest method name differences (e.g. assertEqual($x,$y) and assertEquals($x, $y)) were handled along with crude mimicking of some of SimpleTest’s web_tester functionality.

Anyway, once that was done, it was pretty easy to pinch various bits of config from everywhere and get something like the following build.xml file – when Xinc runs it defines a few properties – so I’ve added in a couple of lines to the build.xml to ensure that these properties are set to something (incase I’m running phing from the command line and not via Xinc).

In my case it was necessary to explicitly exclude e.g. the Zend Framework or ezComponents from various tasks (e.g. phpdoc api generation and code sniffing). In this project’s case the code for each is explicitly within the hierarchy – as opposed to being a system wide include.

Running a particular ‘target’ is just be a case of doing ‘phing -f build.xml tests’ (for instance). phing will default to using ‘build.xml’, so the ‘-f build.xml’ is redundant.

Firing up Xinc (/etc/init.d/xinc start) and tail’ing /var/log/xinc.log give me a good idea of what was going on, and eventually with a bit of prodding I got it all working.

I then thought I ought to integrate test code coverage reports – as they’d be a useful addition and something I can point the customer to – at this point I discovered I needed to hack phing a little to get it to work with phpUnit’s xml output format to create the code coverage report. A patch of what’s needed should be here but phing.info has been down for the last few days… so manually :

In /usr/share/php/phing:

Edit: tasks/ext/phpunit/formatter/XMLPHPUnitResultFormatter.php and change

$this->logger = new PHPUnit_Util_Log_JUnit(null, true) to

$this->logger = new PHPUnit_Util_Log_XML(null, true);

And change the require_once() call at the top of the file to become require_once ‘PHPUnit/Util/Log/XML.php’).

No doubt the above won’t be required once a new release of phing is made – I’m running v2.4.1.

And, if your code has an implicit dependency on various variables being global – and they’re not implicitly declared as global within an include file – it will fail and look like phpunit is trampling on globals; it’s not. Just edit the include file and be explicit with respect to global definition. You will probably need to tell phpUnit to not serialise globals between test calls as some variables ( e.g. a PDO connection) can’t be serialised…. this can be done by setting a property within your test class(es) called backupGlobals to false.

And, if everything works well, you’ll see something like the attached screenshot [[Screenshot 1]]

Summary

Xinc appears unmaintained; patching of it is probably required, but it does appear to work.

I’m glad I’ve finally started to use phing – I can see it being of considerable use in future projects when we have to deploy via FTP or something.

Twitter Weekly Updates for 2010-07-04

  • Sign fail. http://yfrog.com/5sichktj #
  • Looks like the neighbours are holding a donut party for the police …. #
  • Man salt. (I sweat a lot when running, bit surprised it's so visible tho) http://yfrog.com/j8usfej #
  • now lets see if my body can run – http://bit.ly/droitwichrun #
  • At last! last.fm backgrounds on my iphone (3GS with ios4). #
  • Who will win? Patch or my aunt ? (bye patch, I hope) #
  • Can haz new iPhone ? #
  • I might be off to Best Buy in Merry Hill today. That'll be: apple kb, mobo/psu, external drive bays, dvi cables…. Macmini? Self control? #
  • – how is it possible for @myspace to be so shit? it can't be an accident, must be deliberate /via @BluMarTen <- soon: what's myspace? #
  • Of course today
    my work desktop may have died. Coincidence?Conspiracy? Did an apple agent visit and vandalise it ? #macmini for work? #
  • I'm falling in love with my mighty mouse and apple keyboard … Does the mouse work with Linux ? #lazyweb #
  • And a prospect customer I last spoke to a year ago is back in touch…. Glad I now have an extra minion. #palepurple #
  • Thank you @alijamieson for showing my http://klout.com (twitter stats) #
  • Why isn't there a standard bread size which matches up with what toasters can take? All I want is to toast the whole slice…. Come on #eu #
  • I love the new twitterific – shame it didn't update magically. Well worth £2.99 IMHO. #twitterific #
  • Woo. New apple mac mini does dual monitor display out of the box with no config. #whycantubuntudothis ? #shinytoy #itsforworkhonest #
  • See http://bit.ly/ukfoodhygiene for our first iphone app – food hygiene ratings for most of the UK. Pls rate/review 🙂 #opendata #Fsa #food #
  • See http://bit.ly/ukfoodhygiene for our first iphone app – food hygiene ratings for most of the UK. Pls rate/review 🙂 #
  • Fetchez le chien… #
  • The dog has been found….. Alive etc. #
  • The shed of Persia. #swapwordinfilmforshed #
  • The great shed #swapwordinfilmforshed #
  • The green shed #swapwordinfilmforshed #
  • RT @madeupstats 2 in 5 Englishmen now think MILF stands for Match I'd Like to Forget. #
  • RT @paulfabretti: Do we want the England team to return? Surely there are more skilled workers we can allow in before them? #worldcup #
  • RT @asda Free eye test for anyone with a Uruguayan passport after Lampard's goal disallowed: http://bit.ly/eyeoffer <- haha #

Twitter Weekly Updates for 2010-06-27

  • Roads are deserted and it's so peacefully quiet. Can we do this football thing next weekend too ? #
  • I predict England flags and other promotional crap will be very cheap tomorrow and few cars / houses will remain 'decorated' #mysticdavid #
  • I can think of better things to do than be woken by the ninky nonk at 530am on a sunday. If only I could drug him …. #
  • RT @ArmedForces_Day: It's Armed Forces Day! Show your support by retweeting this message http://bit.ly/2nZeL #armedforcesday #
  • RT @PingChat PingChat! Android Beta begins next week! Join the Android page to be eligible! http://bit.ly/cnvF7O – iPhone and blackberry too #
  • One customer handles foreign villa letting. A prospect handles flight bookings. This seems a good match. #
  • Dog gone walking. Hoping he's heading home, safely. The perils of keeping doors open in the hot weather #bromsgrove #
  • RT @madeupstats Social media gurus have on average :
    850 Twitter followers
    410 contacts on LinkedIn
    390 Facebook friends
    1.5 real friends #
  • Failed to jailbreak and upgrade to ios4. stupid pwnage tool. Reverting back to default apple image, will miss bitesms 🙁 #
  • RT @PalePurpleLtd iPhone app accepted 🙂 look for 'food hygiene' by Transparency data – free. <- check out where you eat out. #
  • Losers still outside o2…. Orange is the way toward. #
  • Will there be a geek fight now the iPhone supplies have run out? #
  • RT @madeupstats The Sun newspaper has sufficient stocks of anti-German jokes to last until the year 2051. #achtungschweinhund #
  • So we can win. #eng #
  • Annoyed that I had an off-by-one perception error. Today is not iPhone Thursday … That's tomorrow. #
  • Whole earth's chocolate spread is so very very very nice. #
  • What a lovely morning. #
  • .@rowangoodwin has decided to have a lie in. What a clever, perfect child he Is. #
  • RT @mezzle http://i.imgur.com/17Kkt.jpg <– utter win #ftw #mud #
  • RT @BromsgroveDC News: Sainsbury’s Planning Application to be Heard http://bit.ly/b8GK4q #bromsgrove #
  • Hello $always_late_paying_customer – your website is offline as you've not paid your hosting fees with $third_party … No, I can't help… #
  • Why do I have a cold in the middle of
    Summer? Grr. Rubbish voice etc. #
  • Bromsgrove …. is shit. Photographic proof found – http://twitpic.com/1yi54z #

Twitter Weekly Updates for 2010-06-20

  • My iPhone took the threat of replacement seriously and now all camera pixels work. Grr. #
  • Peace. Perhaps. http://twitpic.com/1ygohu #
  • RT @EmmaEC09 Oxo are bringing out a new cube 4 the world cup. Its gonna have a white wrapper w/ a red cross on it – called 'laughing stock'! #
  • RT @GeneHunt How do you confuse the England football team? ….. Give 'em a football. #ENG #
  • RT @GeneHunt You know you're in the England footie team: sıɥʇ pɐǝɹ ʇ,uɐɔ noʎ ɟı #
  • RT @GeneHunt I was happy when my Scrabble letters spelt out 'England' but then I realised they only amounted to one point. #
  • My scientific selective random sampling of cars shows there are fewer flags today. Was last night a failure and the end of us? #
  • RT @GeneHunt Teenagers drink twice as much as they did 10 years ago. Mind you, they were only aged between 3 and 9 ten years ago. #
  • Wondering how and why nursery have taught Rowan Postman Pat lyrics. Thundercats or something would be better. #
  • Today I'm a bus runner. That's not quite as interesting as it sounds. There was no illegal smuggling involved. #
  • Trainfire is an excellent song. Thanks @dvntownsend #
  • Phew. Got past ticket inspector with invalid ticket. In one stop it'll be valid 🙂 #bookingfail #
  • Spelling fail of the day. http://twitpic.com/1xha0f #
  • Somehow I doubt future nights will be that easy. #
  • Final baby photo for now. Me and Anya Rose (perhaps?) http://twitpic.com/1x70qb #
  • 9lbs. Second 'breakfast' underway. All well. http://twitpic.com/1x6p3m #
  • Second side…. Lots of hair. http://twitpic.com/1x6kyn #
  • It's here. Girl. http://twitpic.com/1x6de7 #
  • Hello baby. #
  • In an ambulance. Labour. #
  • TENs machine thing deployed. #
  • RT @Aypok Finished preparing lunch for today: http://twitgoo.com/zvll4 #
  • The dog has been practicing his coax cable stripping skills on the aerial wires. Good thing I don't have a TV….. #
  • RT @GeneHunt Women's football would be a lot more popular if they renamed it '22 girls and only one cup' #