PodSearch

Under the Radar

211: Logging

 

00:00:00 ◼   ► Welcome to Under the Radar, a show about independent iOS app development.

00:00:04 ◼   ► I'm Marco Arment.

00:00:06 ◼   ► And I'm David Smith. Under the Radar is never longer than 30 minutes, so let's get started.

00:00:10 ◼   ► So, we need to log an event that we have started the show, duly noted.

00:00:14 ◼   ► And then when the show ends, we'll log another event that the show has ended.

00:00:18 ◼   ► And we can use this to make our event log for our podcast.

00:00:22 ◼   ► This is... [laughs]

00:00:24 ◼   ► Logging in apps is about as exciting as this intro has been so far.

00:00:29 ◼   ► But it actually... I have found it to have some significant value.

00:00:33 ◼   ► And some context here for what I'm talking about is...

00:00:37 ◼   ► There's been all sorts of logging frameworks that you can embed into your app

00:00:41 ◼   ► to go beyond just like nslog and to actually have things like

00:00:45 ◼   ► different logs for different things, to have different subsystems of your app

00:00:49 ◼   ► be logging in different ways, customization of how and where they're logged,

00:00:53 ◼   ► persistence of logs, maybe some display of the log on device

00:00:57 ◼   ► for debugging or including in beta bug reports and stuff like that.

00:01:02 ◼   ► And I recently started diving into this world, I guess re-diving into it.

00:01:07 ◼   ► A long time ago I used... What was that one? Cocoa Lumberjack?

00:01:11 ◼   ► I used that forever ago.

00:01:13 ◼   ► That sounds right, but that feels like a very long time ago.

00:01:15 ◼   ► Yeah, and I don't even know... I think it's still maintained, but I haven't used it in a while.

00:01:20 ◼   ► But in the latest Overcast Beta series, part of this update to the app

00:01:25 ◼   ► is that I rewrote a whole bunch of subsystems, or at least I refactored or modernized them

00:01:30 ◼   ► in significant ways. Many of the subsystems of the app are now

00:01:35 ◼   ► rewritten in Swift, many of them are, if not rewritten, at least now interacting

00:01:40 ◼   ► with rewritten components, so there's been a lot of changes under the hood.

00:01:45 ◼   ► And as part of my testing and quality control process, I wanted to have some kind of

00:01:50 ◼   ► persistent logging, that I could log stuff that happened in the app,

00:01:55 ◼   ► and importantly on the watch app, I could log them to a file somewhere in the app's control

00:02:00 ◼   ► and then I could have that file be emailed to me if people had bug reports,

00:02:05 ◼   ► or they could paste it into the slack, or I could even just look at it and see with my own app,

00:02:10 ◼   ► like, what's going on with my app when I'm not connected to Xcode?

00:02:15 ◼   ► Like, what happens overnight? Do I get the background refreshes and stuff like that?

00:02:20 ◼   ► And so I built out, of course, because it's me, I built out my own custom logging thing.

00:02:25 ◼   ► Of course. And it's very simple.

00:02:30 ◼   ► Part of the reason I do these things myself so often is that I want things to be

00:02:35 ◼   ► exactly what I need, but no more than that. I like things to be very simple.

00:02:40 ◼   ► And so my logging quote framework is one file and I think it's, you know,

00:02:45 ◼   ► maybe a hundred lines of code. There's not much to it, but it's good for me.

00:02:50 ◼   ► And the main difference between it and just nslog is persistence to a file,

00:02:55 ◼   ► and that's about it. Pretty much everything else about it is pretty basic.

00:03:02 ◼   ► Just, you know, printing formatted strings with timestamps on them.

00:03:07 ◼   ► But I have found this to be an incredibly useful tool,

00:03:12 ◼   ► not only for just general app quality, but also just to see, like,

00:03:17 ◼   ► the things I've rewritten. Are they working right? You know, are, like, what,

00:03:22 ◼   ► how are they behaving? Are they behaving the way I intended them to behave?

00:03:27 ◼   ► And is there anything about them that is either, you know, that either is broken

00:03:30 ◼   ► or that needs improvement or that could be improved?

00:03:33 ◼   ► And I've found a number of these throughout my Overcast Beta process so far,

00:03:38 ◼   ► thanks to this log that I added. I mean, I just added it maybe a few weeks

00:03:43 ◼   ► or a month ago, so it's actually been pretty recent. But I'm curious, Dave,

00:03:47 ◼   ► do you do anything like this? Any kind of, like, persistent logging and, you know,

00:03:50 ◼   ► bug report log attachment kind of stuff?

00:03:53 ◼   ► So I use it, but only internally. Like, I've never built something like this

00:03:56 ◼   ► in a way that it has ever customer-facing or even beta customer-facing.

00:03:59 ◼   ► It's always been something that, and I think especially, again, on the watch,

00:04:04 ◼   ► it's a situation where I found, I know when I was developing a lot of workout

00:04:08 ◼   ► stuff on the watch, there was a lot, it was just the nature of doing workouts

00:04:12 ◼   ► was that it was very inconvenient to be connected to Xcode while I was, like,

00:04:16 ◼   ► going for an outdoor run. And so I needed to build a bunch of, you know,

00:04:21 ◼   ► like, essentially persistent logging into the application just to the degree

00:04:26 ◼   ► that I could, like, keep track of what was going on and, you know,

00:04:31 ◼   ► identify any bugs or issues or make sure that things were writing to HealthKit correctly.

00:04:34 ◼   ► And so I've done it in that sense, but it's never been something that I've sort of

00:04:39 ◼   ► wrapped up to a point where it would ever be, you know, had a nice, pretty exterior to it.

00:04:42 ◼   ► Mostly what I'm doing is just, like, you know, turning on iTunes file sharing

00:04:47 ◼   ► and having the app just, like, dump a log file into the app's documents directory

00:04:53 ◼   ► that I can pull out from Finder.

00:04:58 ◼   ► But it is one of those funny things that I feel like, you know,

00:05:01 ◼   ► if ultimately the best way to, like, debug a view is to put a border around all your views.

00:05:04 ◼   ► And the best way to debug logic or sort of anything slightly more complicated

00:05:09 ◼   ► is with, like, logging statements.

00:05:14 ◼   ► Like, every year Apple comes out with these amazing cool things in Xcode

00:05:16 ◼   ► where it's, like, their crazy view debugging thing or the memory architecture

00:05:19 ◼   ► or all these things that they've come up with and they keep improving the logging system.

00:05:21 ◼   ► I mean, that's cool, but, like, I find in day-to-day practice,

00:05:26 ◼   ► like, a good, well-placed log statement is just worth its weight in gold.

00:05:29 ◼   ► So it's kind of one of those funny things about being a developer,

00:05:34 ◼   ► is that, like, you know, when I was in the early days of developing,

00:05:36 ◼   ► maybe I thought I was like, "Oh, this is just like what noobs like me do."

00:05:40 ◼   ► But now it's like I'm less of a beginner at this,

00:05:43 ◼   ► but I still, you know, my apps are constantly filled with log statements

00:05:46 ◼   ► and it's such a useful way to visualize kind of turning the sort of multidimensional complexity

00:05:51 ◼   ► of an application into just a linear flow of events.

00:05:58 ◼   ► And that, like, that simplification is so powerful at helping us diagnose problems

00:06:01 ◼   ► or even just, like, verifying that things are working correctly,

00:06:06 ◼   ► even if it isn't in from a purely diagnostic perspective.

00:06:09 ◼   ► Oh, yeah.

00:06:12 ◼   ► And, like, I have found, I mean, you mentioned the, you know, the watch workout case.

00:06:15 ◼   ► This, to me, like, this is where logging is incredible,

00:06:20 ◼   ► because it isn't just about workout apps, it's just any watch app.

00:06:23 ◼   ► Debugging on the Apple Watch is slow and unreliable and is never a very fun process.

00:06:26 ◼   ► And so sometimes you need to know, like, you know,

00:06:33 ◼   ► what was going on during the other 95% of the time that my app exists on my watch.

00:06:36 ◼   ► What's going on that other rest of the time?

00:06:42 ◼   ► Is it getting those background updates?

00:06:41 ◼   ► Is it crashing?

00:06:46 ◼   ► You know, like, there's certain things that are just easier to spot

00:06:47 ◼   ► or pull out of a log file than to try to figure out through, you know, direct debugging methods.

00:06:51 ◼   ► And so this has been kind of, like, my slow process of, like,

00:06:57 ◼   ► modernizing and improving my app, even crash logs.

00:07:01 ◼   ► Like, I added my own crash reporter a few versions ago now,

00:07:06 ◼   ► where it submits to my server any uncaught exception crash logs.

00:07:11 ◼   ► Because Apple's crash logs, I think at the time, and I think still today,

00:07:15 ◼   ► for uncaught exceptions, they don't tell you what the exception was.

00:07:19 ◼   ► They just tell you it's an uncaught exception that was thrown here.

00:07:23 ◼   ► And they might tell you, like, the name of it,

00:07:26 ◼   ► but they won't tell you any of the, like, the parameters

00:07:28 ◼   ► or, like, the description string or anything like that.

00:07:30 ◼   ► So I found it hard to debug that just from Apple's own crash reports,

00:07:32 ◼   ► because I didn't know, like, okay, there was an exception thrown, you know,

00:07:37 ◼   ► on this dictionary line, like, well, it's probably something was nil or something,

00:07:40 ◼   ► but I don't know that for sure.

00:07:43 ◼   ► And it would be nice to know, like, what's the actual message being thrown here.

00:07:45 ◼   ► And so I built in my own very basic, like, uncaught exception handler crash reporter a few months back,

00:07:50 ◼   ► and it sends them to my server.

00:07:55 ◼   ► And I have a little shell script that I can run based on the UUID of each crash that gets reported.

00:07:59 ◼   ► I can automatically look up the symbolicated symbols in my archives

00:08:04 ◼   ► and run this shell script, and it symbolicates the whole crash log for me most of the time.

00:08:09 ◼   ► Symbolication works most of the time.

00:08:15 ◼   ► That's the case with any crash reporting system I've ever worked with.

00:08:18 ◼   ► It's like, most of the time it works perfect.

00:08:23 ◼   ► Some of the times, not at all.

00:08:25 ◼   ► Exactly.

00:08:24 ◼   ► And again, and this is another, you know, I'm building all this stuff myself,

00:08:29 ◼   ► in part because I'm just, you know, that kind of jerk,

00:08:32 ◼   ► and I only trust my own code to do most things,

00:08:35 ◼   ► but also it really keeps things a lot simpler and more privacy conscious.

00:08:37 ◼   ► You know, I don't want to be using some big service to do something that I can do fairly simply myself.

00:08:42 ◼   ► You know, if I need a really big pain in the butt problem solved,

00:08:48 ◼   ► like hosting servers, like, I don't want to physically deal with servers,

00:08:52 ◼   ► so I outsource that to our friends at Linode, and this is not a sponsorship.

00:08:57 ◼   ► I outsource it to Linode because running servers is a really big deal that I don't want to do myself.

00:09:01 ◼   ► But stuff like having a log framework in my app, that's a really small deal.

00:09:06 ◼   ► I don't have massive needs for that.

00:09:10 ◼   ► I need to write statements to a file and be able to get to that file sometimes.

00:09:12 ◼   ► That's it.

00:09:16 ◼   ► And so doing stuff like this myself, I feel like is worth that trade-off.

00:09:18 ◼   ► If you're in a bind and you don't have a lot of time, obviously,

00:09:23 ◼   ► I would understand completely for people who are like, "That's fine for Marco,

00:09:27 ◼   ► but I have to use whatever this free service is by Google or Twitter or Facebook or whatever."

00:09:31 ◼   ► I don't have the kind of needs that would need something big like that when it's something simple like this.

00:09:37 ◼   ► But I do get a lot of value out of having this kind of functionality at all.

00:09:42 ◼   ► And to me, that's a perfect recipe for something that's good to write yourself.

00:09:46 ◼   ► And I think what's interesting there is that sense of identifying the need.

00:09:51 ◼   ► I think it's the first step, though.

00:09:56 ◼   ► In terms of both of these things, what are you actually trying to do?

00:09:58 ◼   ► Is this something that you're trying to ultimately expose to your mainstream users?

00:10:01 ◼   ► Is it going to have a wide audience and user base?

00:10:06 ◼   ► Those are the kind of things that you need to make sure you understand it too ahead of time

00:10:09 ◼   ► for whether it makes sense to build it yourself or even just what this looks like from a privacy perspective

00:10:12 ◼   ► and what the privacy implications are.

00:10:17 ◼   ► It's something that you only expect to turn on and have active, say, during beta builds.

00:10:19 ◼   ► There's a different set of privacy expectations and things that you need to communicate in those contexts

00:10:25 ◼   ► than if it's something that's going to go out to your main big users.

00:10:30 ◼   ► And so I think that's also the thing to keep in mind.

00:10:34 ◼   ► And whether you build it yourself or use a hosted thing, it is one of those

00:10:36 ◼   ► "increasingly I find myself just trying to, as much as I can, just build things myself."

00:10:39 ◼   ► Because honestly, I have such anxiety about all the things going on with the privacy space right now.

00:10:44 ◼   ► With Apple, where they're tracking changes and the IDFA changes and all these things.

00:10:52 ◼   ► There's just so much ambiguity there that it's like, anytime you can just take away one of the,

00:10:56 ◼   ► "Huh, if I include this thing, is it going to end up being a giant pain down the road?

00:11:01 ◼   ► Or am I going to end up being caught up in something where, even if you're not using the parts of that framework or language,

00:11:08 ◼   ► that could be creepy?"

00:11:13 ◼   ► Then your app is flagged by Apple, and App Review looks at you and says,

00:11:16 ◼   ► "Oh, because you linked to this thing, then you have to do it."

00:11:20 ◼   ► And so in that sense, rolling it yourself I think makes sense.

00:11:23 ◼   ► And especially as long as you can roll it out in a way that is reasonable in terms of time it takes to build,

00:11:26 ◼   ► and time and expense in terms of hosting, which is probably fairly manageable.

00:11:32 ◼   ► It's definitely something that I've found myself doing a lot more.

00:11:37 ◼   ► And it's not to your degree, where I think you build everything yourself.

00:11:40 ◼   ► There are a few things that I'll still outsource, but I'm definitely handing in that direction myself over time.

00:11:44 ◼   ► We are sponsored this week by Pingdom.

00:11:52 ◼   ► Do you have a website, and does it have things like a shopping cart or a registration form or a contact page?

00:11:55 ◼   ► If you answered yes to any of those questions, you need Pingdom.

00:11:59 ◼   ► Nobody wants their critical website transactions to fail.

00:12:04 ◼   ► That means a bad experience for your users, and could mean lost business for you.

00:12:07 ◼   ► But the good news is, you can set up transaction monitoring with Pingdom.

00:12:11 ◼   ► Transaction monitoring will alert you when things like cart checkout or forms or login pages fail,

00:12:15 ◼   ► before they affect your customers and your business.

00:12:20 ◼   ► Pingdom can let you know the moment any of them fail, in whatever way is best for you.

00:12:23 ◼   ► You fully customize how you're alerted, who is alerted, when you're alerted,

00:12:26 ◼   ► depending on the outage of severity.

00:12:31 ◼   ► And Pingdom cares about your users having the smoothest site experience possible.

00:12:33 ◼   ► So if disaster strikes, you will be the first to know so you can get in there and fix it.

00:12:37 ◼   ► It's super easy to get started.

00:12:42 ◼   ► I've personally been a Pingdom customer for, oh man, maybe 10 years?

00:12:43 ◼   ► It's been a long time, because it's a great service for monitoring pretty much anything.

00:12:47 ◼   ► So you can see for yourself, Pingdom.com/RelayFM right now,

00:12:52 ◼   ► for a 30 day free trial with no credit card required.

00:12:57 ◼   ► When you sign up, use promo code RADAR at checkout to get a huge 30% off your first invoice.

00:13:02 ◼   ► Once again, Pingdom.com/RelayFM, code RADAR for 30% off your first invoice.

00:13:08 ◼   ► Thanks to Pingdom from SolarWinds for their support of this show and RelayFM.

00:13:13 ◼   ► So I'm curious, I've been using this kind of system in Overcast,

00:13:21 ◼   ► both the logging and then a different kind of logging that I'll get to in a second.

00:13:26 ◼   ► And I've actually made significant quality fixes and usage fixes from this logging.

00:13:29 ◼   ► Last week I found that I had actually forgotten in certain cases

00:13:36 ◼   ► to schedule the next background refresh task for Overcast.

00:13:42 ◼   ► And I was able to verify this by looking at my own log and saying,

00:13:46 ◼   ► "Oh, this is somehow wrong. I'm not getting background refreshes all night long."

00:13:49 ◼   ► And I had a couple of beta testers report the same thing, like,

00:13:54 ◼   ► "Hey, I got a background refresh at midnight and then nothing until 8 in the morning.

00:13:56 ◼   ► It's supposed to be more often than that."

00:14:00 ◼   ► And I was able to look and find the issue, and like, "Oh, I wasn't fixing this correctly."

00:14:02 ◼   ► And so I was able to do it.

00:14:07 ◼   ► One other thing I saw in my main logging is I noticed that

00:14:10 ◼   ► I was running new artwork fetches for podcasts much more often for certain shows than I thought.

00:14:18 ◼   ► And it was necessary.

00:14:23 ◼   ► And I know this because I would see ATP said it had a new artwork version.

00:14:24 ◼   ► And I thought, "I didn't change the artwork for ATP. I'm pretty sure something is wrong here."

00:14:29 ◼   ► You would know. You would definitely know.

00:14:35 ◼   ► Right, and I noticed after every time it would sync artwork, it would say, "ATP's artwork had changed."

00:14:37 ◼   ► And I was like, "That's not right."

00:14:43 ◼   ► And I traced it to actually a server bug that, depending on which server it was,

00:14:45 ◼   ► had checked the artwork.

00:14:50 ◼   ► These two servers had a slightly different version of ImageMagick on them.

00:14:52 ◼   ► And so they would encode the artwork to a different sequence of bytes, depending on which server encoded it.

00:14:56 ◼   ► And so I discovered this whole image bug.

00:15:03 ◼   ► I was able to fix that server side, basically comparing the bytes before compression instead of after.

00:15:07 ◼   ► Which I should have been doing the whole time anyway, but oh well. No one's perfect.

00:15:13 ◼   ► And so I was able to fix this server side bug because I was noticing in my own local logs in the app,

00:15:18 ◼   ► "Hey, this isn't right."

00:15:24 ◼   ► And then the other thing that I was working on, I've gotten some reports here or there over the years of making Overcast.

00:15:26 ◼   ► People often report that it uses a lot of cell data sometimes.

00:15:33 ◼   ► And it's really hard to debug that.

00:15:36 ◼   ► Because especially an app that's designed to let you download large numbers of podcasts,

00:15:39 ◼   ► it's kind of hard to know when someone says it uses a lot of data.

00:15:44 ◼   ► Is that my fault or theirs?

00:15:48 ◼   ► And so I built this whole feature into the current beta version that will be shipping soon

00:15:51 ◼   ► that actually tracks data usage logging.

00:15:55 ◼   ► It actually logs every single bit of data that I can find a way to track my app using.

00:15:59 ◼   ► It logs it.

00:16:04 ◼   ► And this is largely thanks to a thing that I don't know if many people know about.

00:16:04 ◼   ► On NSURL session, there's a delegate method that was added a few OS versions ago.

00:16:09 ◼   ► Something something did finish collecting metrics for task.

00:16:15 ◼   ► And there's this whole URL session task metrics object that will tell you for any URL task that you want to know about,

00:16:19 ◼   ► it'll tell you whether it went through any redirects, what they were,

00:16:25 ◼   ► and then all the byte usage for all their different requests.

00:16:29 ◼   ► It'll send the bytes from the headers, bytes from the bodies.

00:16:30 ◼   ► It tells you all that stuff in this URL metrics object.

00:16:35 ◼   ► And so I went through my app and I audited all the network fetches I could find

00:16:39 ◼   ► and added this metrics collection.

00:16:43 ◼   ► And I have this whole feature now that categorizes and shows you in a similar way to,

00:16:45 ◼   ► I have a storage usage screen that shows you storage by podcast.

00:16:51 ◼   ► I now have a similar screen in the current beta for data usage.

00:16:55 ◼   ► And it'll break down for each podcast.

00:16:55 ◼   ► Like here's how much data was spent on audio, images, sync data and updates, etc.

00:17:00 ◼   ► And what I found was that certain podcasts that I was subscribed to

00:17:06 ◼   ► were sending huge amounts of data as feed updates.

00:17:10 ◼   ► And I noticed, like, wait, why is this feed using like 20 megabytes of data in a day?

00:17:15 ◼   ► That's a ton of feed updates.

00:17:21 ◼   ► And I eventually traced it to the specific issue where certain feeds now,

00:17:23 ◼   ► especially this is very common with user specific private feeds.

00:17:28 ◼   ► So any premium content that you subscribe to that you pay for, or like Patreon feeds, things like that,

00:17:32 ◼   ► where each user gets their own feed and there's like a big hash after it.

00:17:37 ◼   ► ATP's feed works that way as well.

00:17:40 ◼   ► Many of these feeds are now doing hashed enclosure URLs.

00:17:42 ◼   ► So they'll have, at the end of each audio enclosure URL,

00:17:48 ◼   ► they'll have some giant long URL hashed with a time-bombed, time-expiring link,

00:17:51 ◼   ► like an S3 signed URL or something like that.

00:17:56 ◼   ► And every time you fetch the feed, or maybe every 15 or 30 minutes,

00:17:59 ◼   ► those URLs all change.

00:18:04 ◼   ► Which means that every single time this feed is fetched by Overcast servers,

00:18:06 ◼   ► the entire feed has changed because all of its download URLs have changed.

00:18:11 ◼   ► This causes tons of sync data because the way Overcast works is

00:18:17 ◼   ► whenever your app checks in with the servers and something has changed about the feed,

00:18:22 ◼   ► it downloads whatever has changed.

00:18:26 ◼   ► And so these feeds that had per user hashes that would change every hour, 15 minutes or whatever,

00:18:28 ◼   ► they were just causing huge amounts of data transfer,

00:18:35 ◼   ► but the only changes were the enclosure URLs.

00:18:38 ◼   ► And so I was able to fix that even server-side as well,

00:18:40 ◼   ► where I just redirect all downloads now through an overcast.fm/download/giant_long_hash URL.

00:18:46 ◼   ► Which then that redirects to whatever the current enclosure URL is in the feed.

00:18:51 ◼   ► But what that means to the app is that those URLs are no longer changing every hour for all those feeds,

00:18:56 ◼   ► which means that those feeds now have way, way less data usage on the sync side of things.

00:19:01 ◼   ► And I was only able to find that because of all these logging features I'm building into the app.

00:19:08 ◼   ► And so it seems really boring.

00:19:11 ◼   ► This seems like a grunt work boring task,

00:19:16 ◼   ► but I really have gotten a lot of significant value out of just selectively adding a few bits of logging

00:19:21 ◼   ► and a few metric collection things here and there.

00:19:28 ◼   ► And there is also this whole other system I wanted to mention that I haven't looked fully into yet,

00:19:31 ◼   ► but there's an API called MetricKit that was added in iOS 13 and a little bit expanded in iOS 14.

00:19:38 ◼   ► This is a whole Apple API for things like total data usage of your app,

00:19:43 ◼   ► disk writes, crash logs, CPU usage, et cetera.

00:19:48 ◼   ► And it's not real-time, so it's not, you basically get an update once a day or something like that.

00:19:52 ◼   ► I haven't done a lot of work against it yet, but I'm trying to add it into my logging

00:19:57 ◼   ► and have this augment what I'm already logging and check my work on certain areas,

00:20:02 ◼   ► like the network transfer stuff.

00:20:04 ◼   ► And I think it's this great framework that it's not showing you anything new

00:20:09 ◼   ► that you can't just get from the Xcode summary tabs for energy logs and stuff like that.

00:20:14 ◼   ► At least I don't think it is, or at least it's not doing too much more than that.

00:20:21 ◼   ► But it's nice to be able to have that locally in the app

00:20:24 ◼   ► and then to be able to associate certain high-usage scenarios with,

00:20:28 ◼   ► "All right, well, how many podcasts does this person subscribe to?"

00:20:31 ◼   ► And so if somebody subscribes to five podcasts and they're having high data usage,

00:20:36 ◼   ► it's a very different scenario than if they subscribe to 500 podcasts and they have high data usage.

00:20:41 ◼   ► So it's nice to be able to have this kind of stuff in the app

00:20:45 ◼   ► and be able to find other quality issues that your own logging couldn't catch.

00:20:48 ◼   ► Yeah, and I think what's interesting, too, is it's the,

00:20:53 ◼   ► so much of this is about logging lets you check your assumptions.

00:20:57 ◼   ► There's so many of these things where you assume,

00:21:02 ◼   ► you were saying, "I assume that I'm requesting all my background app refreshes.

00:21:05 ◼   ► So if I'm not getting them, it's because the system is doing something wrong."

00:21:10 ◼   ► You've made this assumption that, "Of course, every time I start one, I schedule the next one."

00:21:15 ◼   ► And it lets you check your work on that.

00:21:20 ◼   ► Or you assume, "Why would feeds be changing all the time?"

00:21:22 ◼   ► It's like, "That doesn't make any sense."

00:21:22 ◼   ► There's a reason for that.

00:21:27 ◼   ► There are certain assumptions that I feel are really hard to catch unless you have this,

00:21:28 ◼   ► because you have this data that doesn't care about what your assumption was.

00:21:33 ◼   ► It's just a measurement of what happened in reality, and it lets you catch these things.

00:21:40 ◼   ► Because I know I've run into things where these situations are like,

00:21:45 ◼   ► "Why would there be all this cellular data usage?"

00:21:48 ◼   ► And it's like, in Overcast, you do cellular...

00:21:53 ◼   ► I remember years ago, you were doing battle with the downloader

00:21:57 ◼   ► so that it would only ever download based on your settings of

00:22:02 ◼   ► "Use Wi-Fi or Use Cellular."

00:22:07 ◼   ► So it probably wasn't the syncing of the audio files themselves.

00:22:10 ◼   ► It's going to be something else.

00:22:15 ◼   ► And it's like, "Oh, these are just normal server sync messages

00:22:14 ◼   ► that you send irrespective of Wi-Fi or Cellular."

00:22:19 ◼   ► So in theory, they should be relatively straightforward and small and simple,

00:22:22 ◼   ► but you found a situation where that assumption was invalidated.

00:22:25 ◼   ► And so it's just one of those things that I think logging is so powerful for.

00:22:29 ◼   ► But one thing that I'm just curious about with you is,

00:22:34 ◼   ► when you're making a log, are you annotating that with things other than just the time?

00:22:37 ◼   ► Are you using user-specific tokens?

00:22:43 ◼   ► Or how are you keeping track of this in a way that you can pull back together

00:22:48 ◼   ► the timeline of what happened subsequently at the end?

00:22:52 ◼   ► So there's not much I can pull back because I'm not adding any user data to it.

00:22:56 ◼   ► However, the log doesn't even get to me unless the user sends it to me.

00:23:02 ◼   ► So for privacy reasons, obviously you have to be careful how much you're logging

00:23:08 ◼   ► and what you're logging and where those logs are going.

00:23:11 ◼   ► The way my logs work is they're just files locally,

00:23:16 ◼   ► and the only way you can get to them is on the feedback screen.

00:23:18 ◼   ► There's a button on the right that says "Debug Log."

00:23:22 ◼   ► And again, this is only in the current beta.

00:23:24 ◼   ► This is not in the App Store version yet, but it will be if Apple lets me leave it there.

00:23:25 ◼   ► So you hit "Debug Log," and then it opens up a share sheet with two text files attached.

00:23:30 ◼   ► One from the phone, one from the watch. That's it.

00:23:35 ◼   ► And then you can choose what to do with that information.

00:23:38 ◼   ► If you want to send it to me as part of a report, that's fine.

00:23:37 ◼   ► People have largely figured that out, but that's fine.

00:23:42 ◼   ► So from a privacy perspective, I could theoretically stick a user number in there or something,

00:23:45 ◼   ► but I'd rather not just because I don't really need it.

00:23:52 ◼   ► The main things I put in the log are things like the activity statements,

00:23:55 ◼   ► of things like, "Okay, we're syncing because this feed has changed.

00:24:01 ◼   ► We're syncing because this artwork has changed," etc.

00:24:04 ◼   ► "This download just completed over cellular. This one didn't."

00:24:05 ◼   ► But also I just have basic admin data, like, "Okay, I'm running this build number,

00:24:10 ◼   ► this PID," similar to the nslog prefix where it has the date and the PID.

00:24:14 ◼   ► But also I just add version history, or version number and build number to it.

00:24:20 ◼   ► So that way I can tell when someone's sending a report from the beta,

00:24:23 ◼   ► like, "Okay, which version were they actually running?

00:24:26 ◼   ► Are they running the latest build? Do I know of a certain problem with the one they are running?"

00:24:28 ◼   ► etc.

00:24:29 ◼   ► For the most part, I'm not adding more information than I think I would really need to diagnose particular problems.

00:24:34 ◼   ► So I'm not adding things like their login token or their email address if I have it or anything like that,

00:24:41 ◼   ► because that's just not relevant to the problems I'm trying to solve.

00:24:48 ◼   ► Sure.

00:24:51 ◼   ► That was one of those things that in my past when I've gone down this road is

00:24:52 ◼   ► what's really awkward sometimes is there are certain categories of bugs that are very hard to reproduce generically,

00:24:58 ◼   ► but some users' configuration will reproduce a bug regularly and straightforwardly.

00:25:03 ◼   ► And it's one of those tricky things where sometimes it's like,

00:25:11 ◼   ► I've definitely done the thing where you essentially make a fake login token and login almost as though I'm that person,

00:25:14 ◼   ► but it's always kind of a tricky thing where you don't want to obviously access someone's private data

00:25:21 ◼   ► and get into that in a way that starts to become privacy conscious.

00:25:25 ◼   ► And so it's a really awkward thing where sometimes you want to find this balance between collecting just enough data

00:25:30 ◼   ► that you'd be able to recreate it essentially with fictitious data without needing to go into this specific case of a specific person

00:25:36 ◼   ► and what their specific actual data that would be privacy conscious or privacy a concern is.

00:25:44 ◼   ► And so it's just always such a tricky thing.

00:25:51 ◼   ► It's like, are you keeping track there?

00:25:51 ◼   ► When you say a feed has changed, are you keeping track of the actual feed ID there?

00:25:56 ◼   ► Or just some generic feed has changed?

00:26:01 ◼   ► In that case, that's the specific feed with the feed ID.

00:26:04 ◼   ► It's just a podcast entry.

00:26:09 ◼   ► Overcast, by the way it works, already knows for this user ID number,

00:26:11 ◼   ► they subscribe to feeds X, Y, and Z.

00:26:16 ◼   ► It has to know that.

00:26:17 ◼   ► That's all that is.

00:26:22 ◼   ► Again, I try to minimize the personal data whenever possible.

00:26:24 ◼   ► There are certain cases where I think it's warranted to associate.

00:26:28 ◼   ► One example is on the ATP membership panel.

00:26:33 ◼   ► There's a link to email us with any kind of question about your membership.

00:26:36 ◼   ► And when you do that, it's a mail to link that includes in the subject line your membership number,

00:26:40 ◼   ► like your user ID number.

00:26:42 ◼   ► And on the back end, I have a crappy little admin panel that I can just paste in that number

00:26:47 ◼   ► into either our dashboard or into Stripe's dashboard for payments.

00:26:52 ◼   ► And that number just instantly brings up that customer's account

00:26:56 ◼   ► and whatever info I might need to help them fix their problem.

00:26:59 ◼   ► And that kind of thing I think is totally fine.

00:27:02 ◼   ► You're already my customer.

00:27:05 ◼   ► You're already emailing me about your account,

00:27:07 ◼   ► so I'll make it easier for me to find your account by having this number in the subject line

00:27:09 ◼   ► that you can plainly see.

00:27:14 ◼   ► I feel like that kind of thing is okay.

00:27:16 ◼   ► Yeah.

00:27:18 ◼   ► And I totally agree.

00:27:19 ◼   ► I feel like there's something, in some ways,

00:27:20 ◼   ► the best kind of privacy stuff like this is always the sense of,

00:27:22 ◼   ► it's giving the user control about what they're sharing with you.

00:27:25 ◼   ► And this is another example where it's like,

00:27:29 ◼   ► if you were automatically collecting those log files

00:27:31 ◼   ► and streaming them to a server

00:27:34 ◼   ► and transparently in the background,

00:27:36 ◼   ► which I'm sure there are systems in place in the world

00:27:35 ◼   ► and there are many apps, I'm sure they'd probably even do this.

00:27:40 ◼   ► That starts where you start to get into situations

00:27:42 ◼   ► that become very complicated from a privacy perspective.

00:27:45 ◼   ► And potentially you could find and track down

00:27:48 ◼   ► a whole lot of bugs that way.

00:27:50 ◼   ► As long as it's something where the user is making that choice

00:27:52 ◼   ► and it's a conscious and opaque thing,

00:27:54 ◼   ► whatever the opposite of transparent is.

00:27:58 ◼   ► It's like making sure that it's clear to them.

00:28:00 ◼   ► It's like making sure that it's completely clear to the user

00:28:02 ◼   ► that what they're doing is they're going to email you

00:28:01 ◼   ► and in that email it's going to have a file

00:28:06 ◼   ► and the file isn't some sort of garbled, cryptic thing.

00:28:08 ◼   ► It's like, nope, it's just a plain text file.

00:28:12 ◼   ► They can see exactly what's going with them.

00:28:14 ◼   ► Then it feels like you're in the clear for,

00:28:16 ◼   ► they've made this choice to send it to you

00:28:18 ◼   ► and you're not imposing on their privacy.

00:28:20 ◼   ► You're just responding to something

00:28:23 ◼   ► that they want decided to share to you.

00:28:25 ◼   ► Yeah, exactly.

00:28:26 ◼   ► All right, well, thanks for listening

00:28:26 ◼   ► to this exciting episode about logging.

00:28:31 ◼   ► Hey, don't talk down to logs.

00:28:34 ◼   ► Logs are very important and I think it's time

00:28:37 ◼   ► they finally got their due and I'm glad we got that.

00:28:40 ◼   ► But now we can record that event that the podcast has ended.

00:28:42 ◼   ► Thanks for listening everybody