{"id":246,"date":"2011-11-27T17:07:16","date_gmt":"2011-11-27T21:07:16","guid":{"rendered":"http:\/\/adamrosenfield.com\/blog\/?p=246"},"modified":"2011-11-28T00:11:02","modified_gmt":"2011-11-28T04:11:02","slug":"debugging-a-strange-itunes-permissions-problem-with-dtrace","status":"publish","type":"post","link":"http:\/\/adamrosenfield.com\/blog\/2011\/11\/27\/debugging-a-strange-itunes-permissions-problem-with-dtrace\/","title":{"rendered":"Debugging a strange iTunes permissions problem with DTrace"},"content":{"rendered":"

The other day, I noticed that one of my media files wouldn’t play in iTunes because it decided that my computer wasn’t authorized to play it. I could not authorize my computer to play that song, however, because the iTunes account name associated with that song no longer existed\u2014I had changed the email address of my account in between the time that that was purchased and when I transferred it to my current computer (it was purchased prior to iTunes’ releasing all of their music DRM-free; I strongly oppose DRM<\/a>).<\/p>\n

When I attempted to re-download the track from the iTunes Store, it gave me this error message which would ordinarily be pretty helpful:<\/p>\n

\n

iTunes couldn’t download your purchase.<\/strong><\/p>\n

You don’t have write access for your iTunes Media folder or a folder within it. Change permissions (in the Finder) and then choose Store > Check for Available Downloads<\/p>\n

\n

Alas, that was not the problem. Nothing I can think of would have messed up the permissions, and find(1)<\/a> confirms that all of the subdirectories there are owned by me and are readable, writable, and executable:<\/p>\n

\r\n$ cd ~\/Music\/iTunes\r\n$ find . \\! -user $USER\r\n$ find . -type d \\! -perm -0700\r\n$ # No output from the above commands\r\n<\/pre>\n
What’s going on here?<\/p>\n
Time to dig deeper with DTrace<\/a>.  DTrace is a powerful debugging tool, useful for answering such questions as “What system calls is this process calling?”, “Why is the performance of my server so horrendous?” and many more.  It’s like strace<\/a> on crack.<\/p>\n
But with great power comes great complexity.  In order to use DTrace, you need write a short program in the tool’s D programming language (not to be confused with that other D programming language<\/a>).  The program can be written on the command line or in a separate text file, but it’s still non-trivial.  Some really useful examples can be found here<\/a>, in addition to the various examples in the documentation.<\/p>\n
The error message from iTunes strongly smells like a call to open(2)<\/code><\/a> is failing with EACCES<\/code> when iTunes tries to create the re-downloaded media file.  Let’s see if that’s the case:<\/p>\n
syscall::open*:entry\r\n\/pid == $target\/\r\n{\r\n  printf("%s %s 0x%x 0x%x", execname, copyinstr(arg0), arg1, arg2);\r\n}\r\n\r\nsyscall::open*:return\r\n\/pid == $target\/\r\n{\r\n  printf("errno=%d", errno);\r\n}\r\n<\/pre>\n
Get the PID of iTunes, start tracing it with sudo dtrace -s open.d -p $PID<\/code>, and try to download the file again.  Unfortunately the output is not expected\u2014errors like this get printed many times:<\/p>\n
dtrace: error on enabled probe ID 6 (ID 120: syscall::open:return):\r\n invalid user access in action #2 at DIF offset 24<\/pre>\n
After a little more digging, I discovered that iTunes does not like getting debugged<\/a>, which probably means it also doesn’t like getting itself traced\u2014it just makes the debugger segfault instead.  Fortunately, it’s not too hard to get around this: just turn ptrace<\/code> into a no-op in iTunes when it tries to make itself undebuggable with ptrace(PT_DENY_ATTACH)<\/code>.  Charlie Miller<\/a> provides a nice gdb script for doing so:<\/p>\n
break ptrace\r\ncondition 1 *((unsigned int *) ($esp + 4)) == 0x1f\r\ncommands 1\r\nreturn\r\nc\r\nend<\/pre>\n
Ok, so we’re past that hurdle.  Quit iTunes, restart it under gdb with this anti-anti-debugging technique, fire up DTrace again, and try to re-download the file:<\/p>\n
CPU     ID                    FUNCTION:NAME\r\n  0    119                       open:entry iTunes \/.vol\/234881026\/1516872\/SC Info.sidb 0xa00 0x1b6\r\n  0    120                      open:return errno=13<\/pre>\n
Hmm.  Error 13 is indeed EACCES<\/code>, but what is this strange file under \/.vol<\/code>?  Why, it’s the Volume Management file system<\/a>, used by the Carbon File Manager<\/a>.  Using ls -al \/.vol<\/code>, it appears that that directory is completely empty, yet somehow other file accesses within there succeeded, as indicated in the DTrace output.<\/p>\n
I’m not sure if there’s an easy to figure out which directory in the real file system that \/.vol\/234881026\/1516872<\/code> refers to, but a quick search for a file named “SC Info” yields two likely candidates:<\/p>\n
$ locate -i \"SC Info\"\r\n\/Users\/Shared\/SC Info\r\n\/Users\/Shared\/SC Info~orig<\/pre>\n
Let’s see what those directories look like:<\/p>\n
$ ls -la \/Users\/Shared\/SC\\ Info*\r\n\/Users\/Shared\/SC Info:\r\ntotal 0\r\ndrwxr-xr-x   2 root  wheel   68 Jul  2  2010 .\r\ndrwxrwxrwt  10 root  wheel  340 Oct 30 22:54 ..\r\n\r\n\/Users\/Shared\/SC Info~orig:\r\ntotal 0\r\ndrwxrwxrwx   2 adam  wheel   68 Jul  2  2010 .\r\ndrwxrwxrwt  10 root  wheel  340 Oct 30 22:54 ..<\/pre>\n
Aha!  So iTunes is trying to create a file named SC Info.sidb<\/code> in \/Users\/Shared\/SC Info<\/code>, but it’s failing because I don’t have write access to that directory.<\/p>\n
The solution:<\/p>\n
sudo chmod a+w \/Users\/Shared\/SC\\ Info<\/pre>\n
Bingo!  The song now downloads successfully.<\/p>\n
Of course, you probably could have skipped all this, googled the error message, and found this knowledge base article<\/a> explaining how to fix it without too much trouble, but that’s boring.  Using DTrace to debug the problem is much more fun and exciting!<\/p>\n
Do you have any great success (or failure) stories involving DTrace?<\/p>\n","protected":false},"excerpt":{"rendered":"
The other day, I noticed that one of my media files wouldn’t play in iTunes because it decided that my computer wasn’t authorized to play it. I could not authorize my computer to play that song, however, because the iTunes account name associated with that song no longer existed\u2014I had changed the email address of […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[5],"tags":[],"class_list":["post-246","post","type-post","status-publish","format-standard","hentry","category-programming"],"_links":{"self":[{"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/posts\/246","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/comments?post=246"}],"version-history":[{"count":13,"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/posts\/246\/revisions"}],"predecessor-version":[{"id":260,"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/posts\/246\/revisions\/260"}],"wp:attachment":[{"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/media?parent=246"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/categories?post=246"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/adamrosenfield.com\/blog\/wp-json\/wp\/v2\/tags?post=246"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}