Alternate title for this post was “The Butterfly Effect.” You have have heard about that concept, where a butterfly flapping its wings in New York causes storms in Tokyo or something along those lines. I had a similar moment this weekend when I discovered that a clock being set ahead by one hour resulted in iTunes deleting songs after they were synced to my iPod. It’s a long story, so I’ll start at the beginning.

NetGear Duo Backup Process

My last post on this blog was about how I used a shell script on my NetGear Duo to automate the backup process for my various phpBB2 boards and other web sites. As part of that post I wrote:

To make sure I didn’t miss out on backup files any more I also added a line at the end of the process to email me the results of the backup script. Now each morning I can check my smartphone and confirm that the backup process ran correctly the night before.

For a while this backup process ran just fine. The notification came in to my phone just as expected. Then at some point I noticed that the back up process which was supposed to run at 2AM was instead running at 3AM. I did not worry about it too much. I just assumed that there was something going on with the cron schedule and I would look at it later when I had time. The important issue (downloading the back up files) was being handled, albeit at a different time than expected.

Ancient Virus

Remember nimda? It was a virus that came out back in 2001. I guess the formal classification is that it was really a worm, not a virus, but many folks use the terms interchangeably even though they’re not the same. I had some friends with some older computer hardware that they were trying to retire, but they still had some data on the older machines that they were trying to retrieve. The problem is that the files they needed to move were too big for a thumb drive, this particular computer had no cd-writer (it was from 2000, after all), and they weren’t comfortable removing the hard drive and moving it to a new machine. So they brought it over to my house.

I first tried removing the hard drive and putting it into an external drive chassis to read the files. Interestingly enough, the drive would not get show up. I wasn’t sure why, but that wasn’t the problem I was trying to solve. I noticed that the original computer case had a network port, so I decided to put the hard drive back in the box and connect it to my network. We had already established that the machine would boot up so I knew that would work.

As soon as we did that, my own computer started going crazy, making all sorts of beeps and noises! Turns out that this ancient machine was infected by the Nimda worm, and as soon as it got connected to my network it started to spread. Funny, being attacked by a ten-year old worm! I say “funny” because my AVG installation seemed to be doing its job and properly sending all of the infected files to the quarantine. I guess if you’re in the anti-virus (anti-worm) market, you had better make sure that you can capture anything that’s ten years old just as efficiently as newer stuff.

Ultimately we were able to recover the files for my friends, and I learned my lesson. The next time they brought over a computer I set up an isolated network between their machines rather than attach them to my network.

Interesting footnote: my iTunes library is stored on my NetGear device, both for redundancy and for file sharing purposes. Because it’s shared, that particular volume is open to the network. Because it’s open to the network, I think Nimda dropped a file into every single folder, which I then had to clean up. More on this later.

iTunes Difficulties

Around the same time iTunes released a new version (10.6) that was supposed to handle album artwork better. Now normally I am not a fan of jumping on the latest update. In fact I have my “automatic update” turned off for iTunes just to avoid experiencing a broken system when something that I have is already working. But in this case I had experienced a number of issues with managing my iTunes art, so I decided to install the update. It does, in fact, handle album artwork much better so I was pleased with the update.

A few days later I made a trip to a local used book / compact disc store and came home with a stack of about 20 cds or so. I ripped them using iTunes, reset the artist from “First Last” format to “Last, First” as I like to do, and downloaded album art from my favorite album art site Album Art Exchange. These are all steps that I normally would do. While performing these various steps I was also listening to some of the new music that I had purchased. (”New” is a relative term, as I recall on this particular trip I found a number of “classic rock” artists from the 80’s so it was a nice blast of nostalgia.) Once I had performed all of my updates I synced iTunes to my iPod.

Here’s where it gets weird.

I went back to play some of the songs, and they were gone! The files were physically missing from the hard drive.

Investigation Part I

Remember that earlier I mentioned that my iTunes library is stored on a public network share, and that it had been attacked by Nimda, right? That was the first area I investigated. I first did a full scan of the entire system with AVG. I did a search for the file “droppings” that Nimda had left behind, and when I found them I deleted them or removed them from the AVG quarantine. I wondered if the worm was renaming some of my audio files rather than creating these as new files, but the only songs that were deleted were new ones. Nothing that had been ripped months (or years) ago was being deleted, it was only the new files.

I downloaded some specific scanners designed to find and remove Nimda and confirmed that I was infection free. Now what?

Investigation Part II

I re-ripped the music from cds, and carefully repeated the process. It seemed that once the songs were on the iPod, as long as I recovered them somehow iTunes was fine. It did not do any further deleting. I wasn’t sure what was going on, but at least the problem was something I could recover from. Next I ran a controlled test. Here’s what I did, and what I observed.

1. I ripped three new cds (new meaning ones that I had not ripped from my collection yet)
2. I navigated to the folder and confirmed that all songs had been ripped. I then zipped up the contents of each folder.
3. I made some minor edits to the data once the cds were ripped. As mentioned above, I prefer artist names to be “Last, First” rather than “First Last” so I generally update the artist and the album artist to reflect this. I also have a group tagging strategy, so every song has at least one entry in the grouping field. All of this worked fine.
4. I sync’d to my iPod. But this time I kept a Windows Explorer session open on one of the new folders. Gotcha… I watched some (but not all) of the files disappear.
5. I then checked my iPod. The files were there on the iPod, they just were no longer on my hard drive. Of the 3 new albums, here are the specific details.

   Album 1 – 11 tracks ripped, track 1, 3, 5, 6, 8, and 10 missing after sync
   Album 2 – 9 tracks ripped, track 1 missing after sync
   Album 3 – 11 tracks ripped, all 11 tracks deleted during sync process

   Seemingly a random sequence of events. I am not sure what to make of this right now.

6. To recover I unzipped the archived files I made for each album, and verified that iTunes could see the data (no more ! next to the song).
7. I sync’d to my iPod again. Now remember that the songs already exist on my iPod, they were just deleted from my hard drive. So there’s nothing to update. After the sync (the second time) the songs are still there on the hard drive, still on the iPod, and no issues.

What About Other Data?

At this point I had eliminated the Nimda worm from consideration. I went through some other applications and carefully created specific files on various folders throughout my network disk device. I opened / edited / closed and did a number of other operations. Nothing I did deleted files in other areas of the network disk device, so at this point I eliminated that from consideration. It really seemed to be the iTunes 10.6 update that was the culprit here, but how to fix it?

10.6.1 came out a few weeks later, and I immediately updated. It did not fix my problem.

Investigation Part III – Isolation

I decided to try a different iTunes installation. I repeated this experiment with the same cds on another computer. This computer also has iTunes 10.6 but is only used to sync to an iPhone belonging to my wife. There were no songs on this computer prior to me adding these test albums, so the library is very small. The library on my computer contains over 40,000 songs. Nothing went wrong on my wife’s computer, which is also running Windows XP. The primary difference is that on the second computer the iTunes library is stored locally rather than on the network device.

But I have already done what I can to eliminate the network device as the culprit.

I’m going in circles.

On my last test, back on my computer, I ripped a single cd and did not do any of my normal steps. I ripped and then moved immediately to sync to my iPod. The entire album – all 21 tracks – was deleted. Even the folder was removed!

Butterfly Wings

Yesterday (Sunday) I checked my email for the back up process. It ran, but all of the files were stamped August instead of April, and the year was 1992! I opened a shell session on the network disk device and confirmed that yes, it thought the date was 1992. I opened the administrator tool and confirmed that the date there was also showing as 1992. The device was set up to sync to a time server hosted by NetGear, so I turned that off and reset to the proper time manually. I confirmed that the new date took, and then went back and reset to the NetGear time service. It was back in 1992 again. A quick check of the NetGear forums found several other posts about the same thing, some of which suggested moving to a different time service.

Now it gets interesting. When I moved to a public time service (off of the private NetGear hosted service) not only did I get the correct time, but the hour difference mentioned at the very beginning of this post was also corrected!

All of a sudden a light went off. Could the one-hour time difference be impacting my iTunes?

Problem Resolved

In my earlier tests, when I ripped and immediately synced a single album, it meant that the entire set of songs was processed within an hour. I wondered if these songs were being deleted because iTunes was confused. According to my network disk device, these files would have been ripped one hour into the future! I know iTunes tracks a ton of data, including last played date, last skipped date, and of course the ripped date. Since the ripped date and the file create date on the operating system were out of sync by an hour, I can only assume that iTunes was doing something weird and ultimately deleting the files. The reason the deleting was more random when I ripped a bunch of songs was because (I guessed) the overall process took longer than one hour. If I worked quickly, more songs got deleted. If I took my time, fewer songs were deleted.

To test this concept I deleted the most recent album from iTunes and synced my iPod to clear everything up. I then ripped and synced the same album and none of the tracks got dropped. Everything was processed just fine. Earlier using these same steps all 21 tracks had been deleted.

Ultimately it appears that the Nimda worm was a red herring. It had nothing to do with the issue. The network drives were also functioning perfectly from a mechanical perspective. The network was also fine. I was not having a problem with any other application, only iTunes.

It was a combination of the network time service being wrong in conjunction with some weird program bug in iTunes that was causing random files to disappear. Once I reset my time using a public time service (the same one used for my Windows system) iTunes functioned fine.

That’s the butterfly effect. A clock is wrong by one hour and random music tracks are deleted as they are synced to my iPod.

That was my fun for the month. How was yours?