00:00:16.720
My name is Andrew Noslac. I am the
00:00:19.359
manager of the Rails infrastructure team
00:00:20.800
at Shopify and we are here to do some
00:00:23.600
lightning talks for you today. Uh the
00:00:25.680
theme is new stuff we've built for Rails
00:00:28.400
8.1. Uh so but first just to introduce
00:00:31.119
us this is our team. A nice moody lit
00:00:34.559
photo taken by Aaron Patterson recently.
00:00:37.040
Uh so there we are. Uh what do we do? We
00:00:39.600
work on Ruby and Rails at Shopify. So we
00:00:42.480
help other developers use Ruby and Rails
00:00:44.559
better. We help improve the framework
00:00:46.079
and the language and the other tooling
00:00:47.360
in the ecosystem to help developers at
00:00:49.200
Shopify and developers in the ecosystem
00:00:51.920
like yourselves. That's the mandate we
00:00:54.239
have. Uh I'm going to keep the intro
00:00:56.399
short and sweet. So, there's some uh QR
00:00:58.480
codes you can scan if you want to look
00:00:59.680
at our blog or the Shopy Careers page.
00:01:02.399
Uh, and I'll put this back up at the
00:01:03.920
end. So, yeah, today we're going to talk
00:01:06.080
to you about some new stuff that's in
00:01:07.439
Rails 81 courtesy of us. Uh, this is
00:01:10.400
everything from some like big new
00:01:11.840
features to some small quality of life
00:01:13.680
improvements and bug fixes and uh, yeah,
00:01:16.159
stuff we're really excited to share. So,
00:01:18.240
without any further ado, I'm going to
00:01:19.600
call up our first speaker, uh, Jenny.
00:01:30.880
Whoa, the music is very nice. Um, thanks
00:01:35.040
Andrew. Hey everyone, I'm Jenny and
00:01:37.360
today I'll be sharing a story about
00:01:39.759
eliminating Postgress not null
00:01:42.640
violations. So this story begins many
00:01:45.759
years ago, some say to the origins of
00:01:48.320
Shopify. Um the Shopify monolith is
00:01:51.680
built on my SQL and over um the years
00:01:56.880
we've been doubling down on uh the
00:01:59.360
features it provides and there's a lot
00:02:01.759
of queries that um use my SQL specific
00:02:06.960
uh SQL
00:02:08.959
um we don't necessarily want to be tied
00:02:11.200
down to one database technology and over
00:02:14.640
the last couple of months some people on
00:02:17.760
uh my team like Hartley Nikita, Mikey,
00:02:20.959
some others, and myself have been
00:02:23.120
uncoupling our monolith application code
00:02:25.840
to support multiple databases um and
00:02:29.280
leverage active record more uh for our
00:02:31.840
queries.
00:02:33.760
Uh we've been running tests on Postgress
00:02:36.560
to identify uh my SQL specific behavior
00:02:40.560
and um fix them. So when we ran tests on
00:02:44.720
Postgress, we noticed a lot of um not
00:02:48.000
null violations with the id column. Uh
00:02:51.200
looking at a lot of these cases um kind
00:02:55.040
the code kind of looked like this where
00:02:57.280
there was a insert all and uh we're
00:02:59.920
building an array of records through
00:03:01.760
their attributes. So looking at this
00:03:04.640
closer, um if we have uh a list of
00:03:09.120
objects and they're new, the ID will be
00:03:11.840
nil. And when you take the attributes,
00:03:14.080
there's going to be a hash with the ID
00:03:16.239
key and um the value will be nil. Uh
00:03:19.519
when this is put through an insert all
00:03:22.080
uh my SQL it it works with my SQL
00:03:24.879
because my SQL would just use the auto
00:03:28.080
increment value to determine the ID
00:03:30.560
value. Well, for Postgress, it thinks
00:03:33.120
that you're actually trying to put nil
00:03:35.920
as the ID and this will fail cuz um ID
00:03:40.239
is a not null column.
00:03:43.120
A simple fix to this is just to avoid uh
00:03:47.040
just to remove the ID column for the
00:03:50.080
insert all. However, it's not super uh
00:03:53.840
that simple. Um in this uh example um
00:03:58.480
with customers uh we are um using an
00:04:02.560
upsert all. Uh so in this case there are
00:04:06.080
some records that we want to update
00:04:09.120
while some are um new records and the ID
00:04:13.280
column is nil.
00:04:15.599
To use our previous fix, you could just
00:04:18.720
remove the ID um from all the new
00:04:21.759
records. But this won't work with rails
00:04:24.080
cuz all objects being inserted must have
00:04:27.280
the same keys. Uh another solution a
00:04:31.120
solution to that is that you can split
00:04:33.520
into two queries. One just to insert new
00:04:36.960
records um and another query to update
00:04:40.720
existing records. But we shouldn't
00:04:42.560
really need to have two queries. A
00:04:45.759
better solution is that if there is an
00:04:49.280
ID um that is nil, we can just set that
00:04:53.040
to the SQL default. So tell Postgress to
00:04:57.520
use the default function or the auto
00:05:00.080
increment.
00:05:01.680
Um but why do us developers need to um
00:05:06.639
uh handle these nil values? Um couldn't
00:05:10.320
uh wouldn't it be better if Rails does
00:05:12.400
that? Well, I did put a PR to do exactly
00:05:16.880
that. So the core bulk of this PR is
00:05:20.880
that um when Rails is parsing the uh
00:05:24.720
values list it will um it will if uh the
00:05:30.160
key is a primary key column and the
00:05:33.440
value is nil uh Rails will automatically
00:05:36.160
use the connections default insert value
00:05:38.880
which in most cases is the uh SQL
00:05:42.560
default keyword. So um for Shopify this
00:05:46.960
eliminates the incompatibility between
00:05:49.280
my SQL and Postgress but for all of you
00:05:51.840
guys if you have a Rails app running on
00:05:54.880
Postgress this is just a simple change
00:05:57.440
that um so that you don't need to worry
00:06:00.080
about handling nil values uh for primary
00:06:04.319
key columns when insert and in insert
00:06:08.240
and upsert all. Um, thanks for listening
00:06:11.919
and next up is my awesome colleague
00:06:14.720
George that will talk a little bit about
00:06:17.360
logging.
00:06:28.800
Hello everyone.
00:06:30.720
Hello everyone. I'm George on the Rails
00:06:32.880
infra team and I'm a developer. Uh, so
00:06:35.120
today I want to give you a sneak peek on
00:06:36.960
the new structured event reporter in
00:06:38.479
Rails. giving you an overview about its
00:06:40.639
capabilities and why you should get
00:06:41.919
excited about about its release.
00:06:44.800
So in this quote, DHH gets right to the
00:06:46.720
heart of the problem. As he put it, when
00:06:48.639
you want to aggregate the data from your
00:06:50.479
Rails app into an observability
00:06:52.240
platform, it's a real pain trying to
00:06:54.240
parse the developer focused lines log
00:06:56.479
lines that Rails spits out by default.
00:07:00.479
Uh so the quote perfectly captures the
00:07:02.720
problem. On one hand, we have
00:07:04.000
unstructured human readable log lines
00:07:06.160
which are great in development and for
00:07:07.599
manual inspection. But what Rails is
00:07:09.840
currently missing out of the box is
00:07:11.680
structured logging that can be easily
00:07:13.280
digested by observability tooling. So
00:07:16.240
for years, Rails developers have had to
00:07:18.000
choose either transform unstructured
00:07:20.000
logs to make them queryable or build a
00:07:22.080
custom structured logging solution from
00:07:23.599
scratch.
00:07:25.199
So quickly taking a step back for some
00:07:27.280
additional context. Um as mentioned,
00:07:29.520
Rails provides developers with the
00:07:31.360
ability to create unstructured logs like
00:07:33.440
the one you see here. These logs are
00:07:35.440
generally generally one long
00:07:37.280
unstructured string and with the right
00:07:39.520
tools data platforms like Splunk can
00:07:41.840
parse these logs and make them
00:07:43.120
queryable. For years, our monolith had a
00:07:45.599
custom logging solution built on a
00:07:47.120
system just like this. Splunk is a
00:07:49.120
powerful tool and great text search. It
00:07:51.199
can take a long unstructured string,
00:07:53.360
parse and extract its fields into key
00:07:55.520
value pairs and allow us to quer query
00:07:57.520
previously unstructured logs.
00:08:00.240
So while this worked for a while with
00:08:01.919
the increasing size of our monolith, we
00:08:03.599
recognized a need for a better solution
00:08:05.360
to reduce both our observability costs
00:08:07.599
and query speeds. And with that with
00:08:10.479
that, this let us develop a new
00:08:12.000
structured logger API into Rails
00:08:13.759
directly named Rails.events.
00:08:16.800
So compared to unstructured logs, you
00:08:18.639
can quickly see the difference as
00:08:20.080
instead of a long payload string,
00:08:22.639
structured logs have a clearly defined
00:08:24.319
event name and payload data defined as
00:08:26.400
keyword arguments, enabling data
00:08:28.400
platforms to easily send these logs to a
00:08:30.240
database and make them instantly
00:08:31.680
queryable.
00:08:33.839
We set out to standardize a structured
00:08:35.680
logging system that wasn't yet another
00:08:37.360
custom solution that would only work for
00:08:39.200
Shopify's needs, uh, but something more
00:08:41.440
flexible and upstreamable to Rails. We
00:08:44.159
wanted an opinionated library that helps
00:08:46.000
developers do the right thing and log
00:08:48.000
structured events to as many upstream
00:08:49.680
platforms they wish to send logs to for
00:08:51.440
analysis.
00:08:53.519
In our case of Shopify, our logs first
00:08:55.600
get sent to CFKA as a stream of events
00:08:58.000
which are then processed and stored into
00:08:59.680
a ClickHose database. Our in-house
00:09:01.760
version of data dog observe sits
00:09:03.760
directly on top of this database
00:09:05.440
allowing developers to query structured
00:09:07.120
data efficiently in real time.
00:09:10.320
So setting this all up on your end is
00:09:12.080
straightforward. In your Rails app, you
00:09:13.680
just need to subscribe to your consumer
00:09:15.600
and then within the consumer, you want
00:09:17.120
to you'll want to define the emit
00:09:18.800
method. When an event is created, the
00:09:21.200
event reporter API in Rails will call
00:09:23.120
the emit method on all consumers. So in
00:09:25.519
this pseudo code example, we build the
00:09:26.959
log data, serialize it, and then send
00:09:29.120
lastly send it to CFKA.
00:09:33.440
Coming soon to a Rails near you will be
00:09:35.440
a new first class structured event
00:09:37.279
reporter. It's designed to live
00:09:38.959
alongside rails.logger, not replace it,
00:09:41.279
allowing you to keep your developer
00:09:42.640
focused log lines for development or for
00:09:44.640
debugging while enabling you to use the
00:09:46.720
new event reporter for queryable
00:09:48.320
production grade events. As shown,
00:09:50.560
structured logging provides a handful of
00:09:52.240
benefits, including but not limited to
00:09:54.320
being faster to query, costing less
00:09:56.399
long-term for storage, being type safe,
00:09:58.480
and of course being uniformly formatted.
00:10:02.160
And that's pretty much it. The event
00:10:03.600
reporter will soon be open as a PR
00:10:05.839
upstream to Rails in the coming week
00:10:07.600
where you can leave your review and
00:10:08.880
thoughts. So thanks to these folks
00:10:11.200
Adriana, Jill, Robert, and Francis who
00:10:14.560
are instrumental in the structure
00:10:15.760
structured events work at Shopify. And
00:10:17.760
thank you for listening. So next up,
00:10:19.360
I'll be handing it over to Jill who will
00:10:21.120
also talk about some cool filtered
00:10:22.880
logging work who that she's planning on
00:10:24.959
shipping into Rails.
00:10:36.959
Hi there. I'm Jill and I'm here to talk
00:10:39.519
to you about uh sometimes logs may
00:10:42.320
betray some of your sensitive secrets.
00:10:44.480
Um and the reason that I know about this
00:10:46.079
is because I've found this to be the
00:10:48.640
case in two large Rails applications.
00:10:51.920
and I will give you a little bit of
00:10:53.440
background and talk to you about uh what
00:10:56.000
I found and then uh what I'm adding. Uh
00:10:59.040
Rails is a so quick to get up a new
00:11:02.720
application and that's that's the beauty
00:11:04.480
of it. It's it's so helpful to just
00:11:06.640
scaffold something really quickly. So I
00:11:08.800
scaffolded this in all of like one
00:11:11.040
command in 10 seconds. Uh this is just
00:11:13.760
an application that has credit cards in
00:11:16.800
it. Uh, the only line that I added is on
00:11:19.519
line 28 where I just added one of these
00:11:22.240
unstructured logs that George mentioned
00:11:24.640
here too. Uh, super si, super quick,
00:11:27.440
super simple to get in here. Um, and
00:11:29.920
it's really helpful to get all this
00:11:31.360
stuff in and if you want to see like
00:11:34.000
what's happening, it's really easy to
00:11:35.440
debug. In this case, we are uh looking
00:11:38.959
and rails by default automatically logs
00:11:42.079
all the request parameters that you that
00:11:44.240
you uh that are sent to a controller.
00:11:46.720
So, it's really great for debugging that
00:11:49.279
your request parameters are in here and
00:11:51.360
that the credit card digits are in your
00:11:53.200
request parameters, but doesn't this get
00:11:56.079
sent to the third party data analysis
00:11:58.079
platforms that are all over people's uh
00:12:01.600
production applications? Um, they are.
00:12:05.040
Uh, is that HIPPA approved to send your
00:12:07.680
customers sensitive data? like there
00:12:09.519
there's definitely some data that you
00:12:10.959
want to see in there, but there's other
00:12:12.880
pieces of data that you really probably
00:12:14.399
shouldn't be sending to your thirdparty
00:12:15.839
analysis platforms. Um, is that going to
00:12:18.639
be secure if they get a if they get a
00:12:20.880
leak? It's not the the uh the the nicest
00:12:24.079
thing to do to uh your customers.
00:12:26.959
Luckily, Rails does have a filter
00:12:30.000
parameters configuration that you can
00:12:31.839
add and that you can make sure that
00:12:33.680
anything that's sensitive that you want
00:12:35.360
to keep out of these logs can be
00:12:37.920
filtered. It's in the configuration
00:12:39.839
file. Uh lines 6 through 8 have like new
00:12:43.200
Rails applications. These are the
00:12:44.880
default things that Rails by default
00:12:46.480
filters out of the logs. Um and then in
00:12:49.040
my application, I just added digits in
00:12:51.600
here because that was the credit card
00:12:52.800
digits thing. So from if you have just a
00:12:55.920
newly generated REST application, you
00:12:57.920
can see this view from before where it
00:12:59.600
has all the credit card information in
00:13:01.200
here. If you add it to filter
00:13:02.959
parameters, it has this lovely look in
00:13:04.800
here that says it's filtered, which is
00:13:07.519
great, super helpful. But when you start
00:13:10.800
scaling your Rails application and you
00:13:12.639
start getting hundreds of models, start
00:13:14.720
doing things like that,
00:13:17.279
you don't need to read this. I mean,
00:13:18.720
this is what ends up happening in
00:13:20.240
applications when you get a whole bunch
00:13:21.519
of sensitive information in there. then
00:13:23.200
you have this configuration file that's
00:13:25.200
not in the MVC. It's kind of hidden in
00:13:27.279
configuration and you're not necessarily
00:13:30.240
thinking about this every time that
00:13:31.839
you're adding a new attribute, every
00:13:33.279
time that you're adding something new,
00:13:34.959
you're not looking at the configuration
00:13:37.040
to remember to keep it out of the logs.
00:13:39.279
So, as things get bigger, like how can
00:13:42.560
we make this a little bit easier for
00:13:44.480
Rails developers?
00:13:46.399
Well, we do have something called filter
00:13:48.800
attributes which can live on the model
00:13:50.959
and you can just define that on credit
00:13:52.800
cards digits is a sensitive attribute
00:13:55.279
and you don't have to worry about like
00:13:57.199
finding it in your configuration and
00:13:59.360
because every day you're working in the
00:14:00.959
MVC structure you're looking at that
00:14:02.880
model and remembering oh hey like this
00:14:05.120
is sensitive information I can keep it
00:14:06.800
out of my logs. Uh so that's a solved
00:14:09.680
problem right?
00:14:12.320
Well, the issue with filter attributes
00:14:15.440
is that it only filters some things and
00:14:18.480
not others. So, here's filter parameters
00:14:21.279
filters both the parameters that are
00:14:23.440
coming into your application and the
00:14:25.120
manually created logs.
00:14:27.920
Not so much with filter attributes. It
00:14:30.160
only filters the things that are man in
00:14:32.480
manually created log messages and not
00:14:34.560
the parameters that are coming in. So,
00:14:38.720
if we're talking about the pre-existing
00:14:40.480
stuff that exists in Rails, can you
00:14:42.399
guess what my addition to Rails may have
00:14:44.639
be maybe for Rails 8.1? Um, this is just
00:14:48.399
a quick PR that I put up. Uh, you can
00:14:50.800
scan the QR code or check it out here.
00:14:52.639
It is not yet merged. It is in in the
00:14:55.199
process of being reviewed. You can check
00:14:57.360
it out. You can kind of see how the
00:14:58.959
sausage is made here. Um, but it
00:15:00.800
addresses the problem. So coming up in
00:15:02.959
Rails 8.1, really simply you can go into
00:15:05.760
all of your models and define what is a
00:15:08.000
sensitive attribute in Rails and make
00:15:10.000
sure that when you're in the development
00:15:12.399
process in the day-to-day, it's a little
00:15:14.000
bit more visible for you and a little
00:15:15.680
bit more manageable than a big list in
00:15:17.519
configuration. So uh there's more work
00:15:20.320
to do here. There's lots of things like
00:15:22.480
iterating in this whole process to make
00:15:24.079
it better. Um, I'm going to be around at
00:15:25.839
the Shopify booth if you want to chat
00:15:27.279
about it, but I'm really excited to uh
00:15:29.680
help everybody make their applications a
00:15:31.680
little bit more secure, filtered data a
00:15:33.600
little bit less. Um, next up, we're
00:15:36.079
going to hear from Nikita, who is a
00:15:38.320
fantastic person and secret karaoke
00:15:40.959
machine.
00:15:49.600
Hi everyone. Um today we're going to
00:15:52.399
talk and ask a simple but important
00:15:54.880
question. Do you test your tests? When
00:15:57.279
we write tests, the goal is to catch
00:15:59.519
bugs in our code. But sometimes we have
00:16:01.680
tests that don't actually check
00:16:03.360
anything. They just run. This is where
00:16:05.360
Rails helps us. Rail Scal warn us if
00:16:08.079
there we have tests that don't make any
00:16:09.839
assertions ensuring our tests are truly
00:16:12.079
verifying our code. Let's take a quick
00:16:15.040
look at how that works. Uh yes, I know
00:16:17.839
it's not Rails uh 8.1. It's been
00:16:20.720
introduced a while ago. Hopefully, many
00:16:22.399
of you have the had the opportunity to
00:16:25.279
use this feature. But Rail 7.1
00:16:27.680
introduced a handy feature that warns
00:16:29.519
developers when a test case doesn't
00:16:31.440
perform any assertions. The feature is
00:16:34.000
an after tear down hook. It finds a test
00:16:36.240
with zero assertion and that and if the
00:16:39.120
test that wasn't skipped or errored, it
00:16:41.360
will warn you with the test name and
00:16:43.360
location. This way you can catch and fix
00:16:45.759
tests that aren't actually verifying
00:16:47.440
anything which will keep your test suit
00:16:50.000
reliable. Uh while the rails feature is
00:16:53.519
specifically designed for miniest uh the
00:16:56.000
principle is still universal whether you
00:16:58.639
using miniest or another testing
00:17:00.399
framework or even a different
00:17:02.000
programming language. Uh the intention
00:17:03.920
is the same. Ensure your test actually
00:17:06.240
check what they're supposed to. Now
00:17:08.880
let's have a look at this mini test
00:17:10.880
output. We've got eight tests that run
00:17:13.919
but notice something important. Zero
00:17:15.839
assertions with no skips or failures. Uh
00:17:19.280
this is a perfect example of while why
00:17:22.160
the new Rails feature is so helpful. On
00:17:24.959
the surface, seeing zero failures might
00:17:27.199
make it seem like everything is fine,
00:17:29.120
but zero assertion tells a different
00:17:30.880
story. there is a high chance that these
00:17:33.120
tests aren't checking anything any
00:17:35.520
useful condition or and thus they're not
00:17:38.880
actually verifying our code behavior.
00:17:41.919
This is why testing frameworks emphasize
00:17:44.320
the import the importance of assertions.
00:17:46.720
A passing test suit doesn't necessarily
00:17:48.720
mean that your tests are validating the
00:17:51.360
expected outcomes.
00:17:53.440
Uh with the mini test output showing
00:17:55.520
zero assertions, it's time to dive
00:17:57.200
deeper into the types of tests that
00:17:58.880
might pass without any assertions. Uh
00:18:01.440
these are the tests that execute code
00:18:02.960
but often fail to validate any outcomes.
00:18:06.799
We'll explore a few of common examples.
00:18:10.240
The first one is a test that passes if
00:18:12.320
nothing raised. Uh this test runs a
00:18:14.880
method doesn't raise and it and if it
00:18:17.200
passes uh it passes if no exceptions are
00:18:20.799
thrown. While it does ensure the code
00:18:23.520
execute without any error, it doesn't
00:18:25.919
explicitly verify any specific behavior
00:18:28.240
or outcome. it's relying on the absence
00:18:30.799
of errors as the validation rather than
00:18:33.039
checking for expected results. So to
00:18:35.919
address this issue at the very least we
00:18:38.160
can make an improvement and explicitly
00:18:40.400
check for uh any error not being raised.
00:18:44.240
This test will still rely on the absence
00:18:46.640
of exceptions. At least it ensures the
00:18:48.799
intention is clear and the test
00:18:50.240
framework is actively verifying that no
00:18:52.559
errors occur within the block.
00:18:55.360
The next type of test is an
00:18:56.880
environmentbased test. uh this test is
00:18:59.840
will only run uh the assertion if a
00:19:02.400
certain condition in this case a
00:19:04.080
database adapter check is true. If the
00:19:06.799
condition is false the test effectively
00:19:08.559
does nothing resulting in no assertion
00:19:10.799
being made. Uh the test like this can be
00:19:13.360
problematic because they depend heavily
00:19:15.039
on the runtime environment potentially
00:19:17.360
causing them to pass without actually
00:19:19.120
checking any behavior if the condition
00:19:20.880
isn't met. At the very least, you can
00:19:23.360
use skip to make the to make it explicit
00:19:26.080
when the test condition isn't meant
00:19:28.160
isn't met. Using skip ensures
00:19:30.799
transparency, but comes with a caveat.
00:19:33.200
Uh even when the tests are skipped,
00:19:35.039
their setup block still execute
00:19:36.559
potentially consumer resources and
00:19:38.640
environment like Shopify. We use a
00:19:40.320
distributed execution model which means
00:19:42.559
the an empty test will still be
00:19:44.160
allocated to a worker and execute. uh a
00:19:47.360
more effective solution especially
00:19:49.440
environments like Shopify where we treat
00:19:52.320
skip test as a
00:19:54.960
uh as something we need as a temporary
00:19:57.600
solution as something that needs uh
00:19:59.600
attention in the future is to not define
00:20:02.559
the test at all under the condition. By
00:20:05.760
conditionally defining the test we avoid
00:20:08.080
cluttering our test suit um with test
00:20:11.200
cases that irrelevant to the current
00:20:14.559
environment.
00:20:17.120
Uh our next example will focus on
00:20:19.520
iterating over over the collection like
00:20:21.840
in the following test. Uh the issue here
00:20:24.400
may arise when the collection the
00:20:26.320
published post is empty. In this case
00:20:28.480
the l the loop won't be executed which
00:20:31.200
result in no assertions being made. The
00:20:33.600
test then passes by default potentially
00:20:35.840
missing important validation.
00:20:38.159
To tackle this issue of potentially
00:20:40.159
collections, we modify our test to
00:20:42.320
ensure it allows it always performs
00:20:44.799
meaningful check. Uh the revised test
00:20:47.679
has a uh published post empty check with
00:20:52.080
a flank which will fail the test if the
00:20:54.799
collection if the collection suddenly
00:20:56.720
becomes empty due to changes to our
00:20:58.960
fixture files or the any kind of
00:21:01.919
database setup mechanism.
00:21:04.320
uh it will signal that the expected data
00:21:06.720
wasn't available for validation
00:21:08.799
prompting developer further
00:21:10.400
investigation.
00:21:12.559
The next one is a generalized version of
00:21:15.280
a test that would rely heavily on
00:21:17.520
mocking or stubbing. Um in this case we
00:21:20.640
are using mini test mock to verify that
00:21:22.480
my method is called uh with the expected
00:21:24.799
arguments and returns the expected
00:21:26.640
value. Uh the key issue here or the
00:21:29.600
potential issue here is arises when uh
00:21:32.240
we don't do anything to verify that the
00:21:35.440
method is being called in this example
00:21:37.200
we use mock.verify verify which at the
00:21:39.760
very least will fail the test. If no u
00:21:42.720
if the my method wasn't called but a
00:21:44.880
better alternative for mini test would
00:21:46.960
be to use an assert mock helper which is
00:21:49.679
an actual assertion and does increment
00:21:51.760
the assertion counter. But as I
00:21:53.679
mentioned overall this is a bad example
00:21:55.520
of the test that uh relies heavily on
00:21:58.960
implementation details and doesn't
00:22:01.120
assert or test any kind of application
00:22:03.520
behavior.
00:22:05.520
uh for those of you working with RSpec
00:22:07.600
while it currently lacks uh counter for
00:22:11.200
expectations there is an open issue for
00:22:13.520
this feature pins and implementation. So
00:22:15.360
if you're interested this could be great
00:22:17.679
opportunity to contribute to our spec uh
00:22:22.080
finding tests overall finding test
00:22:24.159
without assertion is a great chance for
00:22:26.240
open source contribution. This is a
00:22:28.320
great reason to explore an open source
00:22:30.640
application or a library uh and make
00:22:32.799
your first contribution. Whether it's
00:22:34.880
going to be enhancing test tools to
00:22:36.559
catch assertionless tests or adding new
00:22:38.400
feature, this is your chance to dive in
00:22:41.360
the open source world and make an
00:22:43.280
impact. Personally, relying on this
00:22:46.080
feature, I was able to make a few
00:22:47.440
contributions to Rails removing or
00:22:49.600
improving some uh assertionless tests.
00:22:52.799
Uh so I welcome you doing similar thing
00:22:56.240
and thanks. Uh next I invite uh the host
00:23:00.559
of this lightning talk show and our team
00:23:03.120
lead Andrew.
00:23:12.400
All right. Who is just about ready for
00:23:15.280
lunch?
00:23:17.039
Yeah, I am. Uh so we have one more I
00:23:19.840
have one more uh lightning talk to share
00:23:22.320
with you uh and then I'm gonna go get a
00:23:24.240
Philly cheese steak personally. So I
00:23:25.919
invite anyone to join me. Um yeah I'm
00:23:28.480
going to talk about the Rails error
00:23:29.679
reporter middleware which is new. It's
00:23:31.360
coming in 8.1. Uh so who knows about the
00:23:34.480
Rails error reporter or uses it in their
00:23:36.559
app? Anyone? You should use it. It's
00:23:39.360
great. So the Rails error reporter is a
00:23:41.679
unified way to report errors in an app.
00:23:43.840
Uh it works with a subscriber model. Uh
00:23:46.240
this is pseudo code. It's not the code
00:23:48.080
in Rails. Uh actually, sorry, this is a
00:23:50.320
demonstration. So, uh yeah, you can add
00:23:52.559
some subscribers. So, here we have a log
00:23:54.320
subscriber and a metric subscriber. Uh
00:23:56.799
and then there's a method for like
00:23:58.159
handling an error. So, if an error is
00:23:59.520
raised or if we just pass an error to
00:24:01.039
the report method, then it will fire off
00:24:03.120
to those subscribers. Um so, this is
00:24:05.280
what it looks like under the hood in
00:24:06.559
Rails. This is like kind of a pseudo
00:24:09.600
code version, but basically it iterates
00:24:11.120
through each of the subscribers and
00:24:12.480
sends a report to them with the error
00:24:14.080
and some of the other metadata. uh and
00:24:16.480
then each of the subscribers implements
00:24:18.080
a report method. So uh the log subri
00:24:20.559
subscriber is sending uh our error to
00:24:22.720
the logs and the metric subscriber is
00:24:24.880
sending them to stats d in our case
00:24:26.480
which is what we use for metrics at
00:24:28.159
shopify. So yeah this was in implemented
00:24:30.720
back in rail 7 uh and to be quite honest
00:24:33.360
at Shopify we did not do a very good job
00:24:35.919
of actually implementing it in our app.
00:24:38.320
We had just one subscriber uh which was
00:24:40.799
called public exception.log. Uh this was
00:24:43.279
a god class that had a lot of reporting
00:24:45.840
concerns all mixed together. Logging
00:24:47.679
metrics, bug tracking stuff, other
00:24:49.600
stuff, whatever that is. Uh it was very
00:24:52.240
hard to reason about what this thing
00:24:53.520
does. And we found that often when like
00:24:55.760
changing code for one of the subs or one
00:24:57.520
of the concerns would like accidentally
00:24:59.440
break or affect uh some of the logs
00:25:01.919
coming for the other cons like for one
00:25:03.440
of like changing the logging concern
00:25:06.640
would like accidentally break something
00:25:07.919
in the error tracker which would like
00:25:09.520
drive everyone crazy. Um, last year at
00:25:11.760
Shopify, we had this big push to
00:25:13.279
standardize our error tracking. And as
00:25:15.760
part of that, I tried to do a big
00:25:17.600
refactor of this uh, and use the Rails
00:25:20.640
error reporter more how it's meant to be
00:25:22.960
used with multiple subscribers. So, my
00:25:24.880
goal was to go from public exception to
00:25:27.520
four subscribers, error tracker, metric
00:25:29.440
subscriber, log subscriber, and a query
00:25:31.200
timeout subscriber. That way, they could
00:25:32.720
all have their own concerns and like be
00:25:34.320
tested individually and isolated from
00:25:36.000
each other, just like uh, Rails and
00:25:38.000
Tens. Uh but I ran into kind of an issue
00:25:40.240
which is uh how do I share code between
00:25:42.559
the subscribers? So they actually have
00:25:44.400
some overlapping concerns that they all
00:25:46.159
want to do. We have uh an exception
00:25:48.480
classification system. Uh we also walk
00:25:50.799
the back trace to find out who like
00:25:52.799
caused the exception and that lets us
00:25:54.400
like tag the team. Uh and all the
00:25:56.880
subscribers care about that. So the
00:25:58.880
problem is like we would end up with
00:26:00.080
some duplicate code in each of the
00:26:01.440
subscribers and some of this stuff is
00:26:03.279
maybe a little timeconuming. So we could
00:26:04.880
also be doing duplicate work if we're
00:26:06.400
not careful. Uh so yeah, that's a
00:26:09.120
picture of me. Uh I started thinking
00:26:10.640
about how I can solve this. Um you know,
00:26:13.520
I thought of some like really naive and
00:26:15.600
not very good solutions. Like what if I
00:26:17.440
just like stuff this on an instance
00:26:18.960
variable on the error itself. So okay,
00:26:21.120
I'm going to do all the work to get the
00:26:22.880
uh error classification and then I'll
00:26:24.400
just like put it on in an instance
00:26:25.600
variable and then one of the other
00:26:26.720
subscribers can like pull it off. Um
00:26:29.120
obviously, I mean maybe not obviously.
00:26:30.960
Obviously to me this code is really not
00:26:33.279
nice. Like here's an example. maybe I
00:26:34.799
put it into a uh concern that they can
00:26:37.200
all share. Um, but I don't really like
00:26:39.520
um messing around with the instance
00:26:41.520
variables on the error. So, I thought,
00:26:43.120
you know, it seems like Rails is like
00:26:44.640
missing something for this case where I
00:26:46.159
want to share code. Uh, and it was uh I
00:26:50.080
added this uh with my friend Sam, my
00:26:52.240
co-orker Sam, we added this middleware.
00:26:54.400
Um, so the middleware is now sitting
00:26:56.960
between when you call the error report
00:26:58.960
and when we uh actually call all the
00:27:00.880
subscribers and it lets you add some
00:27:02.559
extra metadata to your error report um
00:27:05.120
that you can then fire off to all the
00:27:06.799
subscribers. So what that looks like is
00:27:09.039
again this is like pseudo code. The code
00:27:10.640
in Rails is a little more complex but
00:27:12.240
this is roughly what it looks like. So
00:27:14.640
uh we have two middlewares here. For
00:27:16.320
example, there's an error attribution
00:27:17.840
middleware and an error classification
00:27:19.600
middleware. And what happens when we
00:27:21.360
call reports uh or handle as well? Uh we
00:27:24.400
go through each of the middlewares and
00:27:26.000
we inject them uh we inject them with
00:27:27.919
the context. So the middleware uh we
00:27:30.080
call the middleware and then the
00:27:31.679
middleware is able to update the error
00:27:33.679
context with any extra metadata that it
00:27:35.919
has. Then that's the context that we
00:27:37.600
pass to all the subscribers. So the
00:27:39.840
middleware themselves have a very simple
00:27:41.679
API. They just have this call method. Uh
00:27:43.760
and what call does is it takes the error
00:27:45.760
and the context. We can do any code that
00:27:47.840
we like. Uh so here we're using our
00:27:49.679
error classifier to classify the error
00:27:51.520
and then we're getting that
00:27:52.400
classification and we're putting it on
00:27:54.000
the context. Uh and then we return the
00:27:56.000
context and then that context hash is
00:27:57.919
passed along to each of the subscribers.
00:28:00.080
Um and yeah, this was a big success. It
00:28:02.159
led to us having a very nice like clean
00:28:04.000
architecture for all our reporting. So
00:28:05.600
now we have three or four subscribers.
00:28:07.520
We actually ended up with quite a few
00:28:08.880
middleares with different concerns. Um
00:28:10.720
and we were able to extract those into a
00:28:12.399
gem. So now all of Shopify has the same
00:28:14.559
middlewares and all the different Rails
00:28:16.000
apps that we have and some of the same
00:28:17.679
subscribers. Um so yeah, this was a very
00:28:20.320
nice success taking one gigantic like
00:28:22.880
500 line class basically and kind of
00:28:25.120
composing it in all these little parts.
00:28:27.440
Um so yeah, highly recommend using both
00:28:29.440
the error reporter and uh once you're on
00:28:31.440
Rails 8.1 uh the middleares as well. Uh
00:28:35.039
yeah.
00:28:36.559
Oh, one gotcha. Yes, sorry. One gotcha I
00:28:39.360
wanted to call out about this is that
00:28:40.720
the context is getting mutated. That's
00:28:42.480
something to really remember. So, uh,
00:28:44.559
we're passing this context between each
00:28:46.159
of the subscribers. And so, we need to
00:28:47.760
know or you need to know that, uh, if
00:28:50.799
your logs are, uh, sorry, if in this
00:28:54.720
case I have a PII middleware, which for
00:28:56.720
some reason is adding someone's personal
00:28:58.399
identifying information to, uh, the
00:29:00.559
context, which I don't know why you
00:29:01.919
would do, but maybe it's something you
00:29:03.039
would do. If later on in one of our
00:29:05.120
subscribers, we're splatting out that
00:29:06.799
context, then we're actually going to be
00:29:08.399
logging some of that PII. So the one
00:29:10.799
call out is that this is now like a
00:29:12.320
mutable context that's coming through
00:29:13.840
like all the middleares to your
00:29:15.760
subscriber. Uh so yeah that's uh that's
00:29:18.559
one caveat. Um yeah, happy error
00:29:21.440
reporting. That's it for me. Uh and
00:29:23.440
that's it for Shopify. So here is all of
00:29:25.600
our uh blog and our careers page.
00:29:30.799
Thank you. Uh enjoy lunch and come find
00:29:33.279
us at the booth if you have questions.
