diff --git a/Gemfile b/Gemfile index 17463e74e..e7ee0d08a 100644 --- a/Gemfile +++ b/Gemfile @@ -32,7 +32,6 @@ group :test do end group :spec do - # Using feature branch until https://github.com/Shopify/liquid-spec/pull/144 is merged - gem 'liquid-spec', github: 'Shopify/liquid-spec', branch: 'self-drop-env-lookup-specs' + gem 'liquid-spec', github: 'Shopify/liquid-spec' gem 'activesupport', require: false end diff --git a/Rakefile b/Rakefile index e14d49aa6..8f4639205 100755 --- a/Rakefile +++ b/Rakefile @@ -5,21 +5,42 @@ require 'rake/testtask' $LOAD_PATH.unshift(File.expand_path("../lib", __FILE__)) require "liquid/version" +template_recorder_test = "test/integration/template_recorder_test.rb" + task(default: [:test, :rubocop]) desc('run test suite with default parser') Rake::TestTask.new(:base_test) do |t| t.libs << 'lib' << 'test' - t.test_files = FileList['test/{integration,unit}/**/*_test.rb'] + test_files = FileList['test/{integration,unit}/**/*_test.rb'] + test_files.exclude(template_recorder_test) unless ENV["LIQUID_TEMPLATE_RECORDER_HOOKS"] + t.test_files = test_files t.verbose = false end Rake::TestTask.new(:integration_test) do |t| t.libs << 'lib' << 'test' - t.test_files = FileList['test/integration/**/*_test.rb'] + test_files = FileList['test/integration/**/*_test.rb'] + test_files.exclude(template_recorder_test) unless ENV["LIQUID_TEMPLATE_RECORDER_HOOKS"] + t.test_files = test_files t.verbose = false end +desc('run template recorder tests with hooks enabled') +task :template_recorder_test do + sh( + { + "LIQUID_PARSER_MODE" => "lax", + "LIQUID_TEMPLATE_RECORDER_HOOKS" => "1", + }, + "bundle", + "exec", + "ruby", + "-Itest", + template_recorder_test, + ) +end + desc('run test suite with warn error mode') task :warn_test do ENV['LIQUID_PARSER_MODE'] = 'warn' @@ -59,6 +80,8 @@ task :test do Rake::Task['integration_test'].reenable Rake::Task['integration_test'].invoke end + + Rake::Task['template_recorder_test'].invoke unless ENV["LIQUID_TEMPLATE_RECORDER_HOOKS"] end task(gem: :build) diff --git a/docs/template_recorder.md b/docs/template_recorder.md new file mode 100644 index 000000000..e6aeb6726 --- /dev/null +++ b/docs/template_recorder.md @@ -0,0 +1,78 @@ +# Recording and replaying renders + +`Liquid::TemplateRecorder` captures successful template renders so they can be +replayed without the application's file system or Drop implementations. +Recording does not wrap or replace assigns, so the recorded render has the same +semantics as a normal render. + +The instrumentation hooks are disabled by default. Set +`LIQUID_TEMPLATE_RECORDER_HOOKS=1` before the process loads Liquid. This is a +boot-time setting; changing it after Liquid is loaded has no effect. Calling +`Liquid::TemplateRecorder.record` while the hooks are disabled raises an error +instead of silently producing an incomplete recording. + +```ruby +Liquid::TemplateRecorder.record("render.json") do + template = Liquid::Template.parse(source) + template.render!(assigns) +end + +replayer = Liquid::TemplateRecorder.replay_from("render.json", mode: :verify) +replayer.render # raises if the output changed +``` + +A recording contains the root template, every parsed partial, partial contents, +plain Hash/Array values resolved by the template, properties actually read from `Liquid::Drop` objects, +filter-call diagnostics, engine options, and the rendered output. Drop instance +variables are never inspected. An unsupported Ruby object raises +`Liquid::TemplateRecorder::SerializationError` rather than silently producing a +recording that cannot be replayed. + +## Storage formats + +A `.json` destination is written atomically after the recording block succeeds. +It contains a session with every render performed by the block. + +A `.jsonl` destination is append-only. Each successful top-level render is one +compact, self-contained JSON line. This is the recommended format for production +sampling: a process failure can lose at most the render being written, writers +are serialized with `flock`, and a recording can be replayed by index. + +A destination may instead be any writer object responding to `write(record)`. The +writer receives one self-contained recording Hash per successful render. Liquid +does not own or close injected writers, so applications can publish records to +Kafka, object storage, or another transport without coupling that transport to +the recorder. +Pass `on_error:` to keep serialization or sink failures out of the render path; +the callback receives the error and should not raise. + +```ruby +Liquid::TemplateRecorder.record(kafka_writer) do + template.render!(assigns) +end +``` + +```ruby +Liquid::TemplateRecorder.replay_from("renders.jsonl") # last render +Liquid::TemplateRecorder.replay_from("renders.jsonl", index: 0) # first render +Liquid::TemplateRecorder.records("renders.jsonl") # inspect all +``` + +Compression is intentionally separate from the schema. In particular, one +long-lived compressed stream makes appending, recovery, and selecting a render +harder. Compress rotated `.jsonl` files with the storage system of your choice; +a future compressed writer can use one independent frame per record without a +schema change. + +Recording sessions are thread-local. Nested sessions in the same thread are +rejected. Existing application register names and the one-argument +`FileSystem#read_template_file` API remain unchanged. + +## Replay modes + +* `:compute` runs filters normally. Pass application filters with + `replayer.render(filters: MyFilters)`. +* `:strict` returns each exact recorded filter result and rejects a changed + filter sequence. This can replay application-specific or nondeterministic + filters without loading their implementations. +* `:verify` computes normally and raises when the final output differs. diff --git a/lib/liquid.rb b/lib/liquid.rb index dce089772..b6034c233 100644 --- a/lib/liquid.rb +++ b/lib/liquid.rb @@ -90,3 +90,4 @@ module Liquid require 'liquid/usage' require 'liquid/registers' require 'liquid/template_factory' +require "liquid/template_recorder" diff --git a/lib/liquid/block_body.rb b/lib/liquid/block_body.rb index e4ada7d16..e7d6ffd4e 100644 --- a/lib/liquid/block_body.rb +++ b/lib/liquid/block_body.rb @@ -84,10 +84,15 @@ def self.raise_missing_variable_terminator(token, parse_context) # @api private def self.render_node(context, output, node) + recorder = TemplateRecorder::HOOKS_ENABLED ? TemplateRecorder.current : nil + tag_call = recorder&.begin_tag_render(node, context) + output_start = output.length node.render_to_output_buffer(context, output) rescue => exc blank_tag = !node.instance_of?(Variable) && node.blank? rescue_render_node(context, output, node.line_number, exc, blank_tag) + ensure + recorder&.finish_tag_render(tag_call, output[output_start..]) if output_start end # @api private diff --git a/lib/liquid/context.rb b/lib/liquid/context.rb index 30492578e..3cc6193ab 100644 --- a/lib/liquid/context.rb +++ b/lib/liquid/context.rb @@ -228,6 +228,8 @@ def find_variable(key, raise_on_not_found: true) liquid_variable.context = self if variable != liquid_variable && liquid_variable.respond_to?(:context=) + recorder = @registers[TemplateRecorder::REGISTER_KEY] if defined?(TemplateRecorder) && TemplateRecorder::HOOKS_ENABLED + recorder&.emit_variable_read(key, liquid_variable) liquid_variable end diff --git a/lib/liquid/drop.rb b/lib/liquid/drop.rb index d13398ec4..3b97943b4 100644 --- a/lib/liquid/drop.rb +++ b/lib/liquid/drop.rb @@ -37,11 +37,20 @@ def liquid_method_missing(method) # called by liquid to invoke a drop def invoke_drop(method_or_key) - if self.class.invokable?(method_or_key) + result = if self.class.invokable?(method_or_key) send(method_or_key) else liquid_method_missing(method_or_key) end + + # A host application may assign its own object as a drop's context, and a + # drop can be invoked outside any render. Neither case has registers, and + # instrumentation must never turn either into a NoMethodError. + if defined?(TemplateRecorder) && TemplateRecorder::HOOKS_ENABLED && @context.respond_to?(:registers) + recorder = @context.registers[TemplateRecorder::REGISTER_KEY] + end + recorder&.emit_drop_read(self, method_or_key, result) + result end def key?(_name) diff --git a/lib/liquid/partial_cache.rb b/lib/liquid/partial_cache.rb index f49d14d90..d1b45d391 100644 --- a/lib/liquid/partial_cache.rb +++ b/lib/liquid/partial_cache.rb @@ -10,6 +10,10 @@ def self.load(template_name, context:, parse_context:) file_system = context.registers[:file_system] source = file_system.read_template_file(template_name) + if defined?(TemplateRecorder) && TemplateRecorder::HOOKS_ENABLED + recorder = context.registers[TemplateRecorder::REGISTER_KEY] + end + recorder&.emit_file_read(template_name, source) parse_context.partial = true diff --git a/lib/liquid/strainer_template.rb b/lib/liquid/strainer_template.rb index ca0626dda..94b85cb1f 100644 --- a/lib/liquid/strainer_template.rb +++ b/lib/liquid/strainer_template.rb @@ -48,13 +48,21 @@ def filter_methods end def invoke(method, *args) - if self.class.invokable?(method) + result = if self.class.invokable?(method) send(method, *args) elsif @context.strict_filters raise Liquid::UndefinedFilter, "undefined filter #{method}" else args.first end + + # See Drop#invoke_drop: the context is not guaranteed to be a + # Liquid::Context, and instrumentation must not raise. + if defined?(TemplateRecorder) && TemplateRecorder::HOOKS_ENABLED && @context.respond_to?(:registers) + recorder = @context.registers[TemplateRecorder::REGISTER_KEY] + end + recorder&.emit_filter_call(method, args.first, args.drop(1), result) + result rescue ::ArgumentError => e raise Liquid::ArgumentError, e.message, e.backtrace end diff --git a/lib/liquid/template.rb b/lib/liquid/template.rb index 70ff00816..501df877d 100644 --- a/lib/liquid/template.rb +++ b/lib/liquid/template.rb @@ -105,6 +105,9 @@ def parse(source, options = {}) tokenizer = parse_context.new_tokenizer(source, start_line_number: @line_numbers && 1) @root = Document.parse(tokenizer, parse_context) + if defined?(TemplateRecorder) && TemplateRecorder::HOOKS_ENABLED && TemplateRecorder.current + @template_recorder_source = source.dup.freeze + end self end @@ -141,6 +144,10 @@ def errors def render(*args) return '' if @root.nil? + if defined?(TemplateRecorder) && TemplateRecorder::HOOKS_ENABLED + recording_session = TemplateRecorder.current + end + recording_assigns = args.first context = case args.first when Liquid::Context c = args.shift @@ -180,6 +187,13 @@ def render(*args) context.add_filters(args.pop) end + recording = recording_session&.begin_render(self, recording_assigns, context) + if recording + recorder_registers = context.registers.static + previous_recorder = recorder_registers[TemplateRecorder::REGISTER_KEY] + recorder_registers[TemplateRecorder::REGISTER_KEY] = recording + end + # Retrying a render resets resource usage context.resource_limits.reset @@ -189,12 +203,43 @@ def render(*args) context.template_name ||= name + rendered_output = nil + render_succeeded = false + # A caller may hand in a buffer that already holds bytes this template did + # not produce, and may keep appending to it after this render returns. The + # recording must describe only what the template rendered, so remember + # where its output starts. + recorded_output_start = recording ? (output || '').bytesize : 0 begin # render the nodelist. - @root.render_to_output_buffer(context, output || +'') + rendered_output = @root.render_to_output_buffer(context, output || +'') + render_succeeded = true + rendered_output rescue Liquid::MemoryError => e - context.handle_error(e) + rendered_output = context.handle_error(e) + # The caller still gets the error text, but a render that hit the memory + # limit is truncated by definition: recording it as a success would put + # a partial render into the corpus as if it were the specified output. + render_succeeded = false + recorded_output_start = 0 + rendered_output ensure + if recording + if previous_recorder + recorder_registers[TemplateRecorder::REGISTER_KEY] = previous_recorder + else + recorder_registers.delete(TemplateRecorder::REGISTER_KEY) + end + # Slice off any caller-supplied prefix, and copy: the buffer is the + # caller's and may still be appended to, which would otherwise leak + # bytes into a recording that has already been taken. + recorded_output = if rendered_output.is_a?(String) + rendered_output.byteslice(recorded_output_start, rendered_output.bytesize - recorded_output_start).dup + else + rendered_output + end + recording_session.finish_render(recording, recorded_output, context, success: render_succeeded) + end @errors = context.errors end end diff --git a/lib/liquid/template_recorder.rb b/lib/liquid/template_recorder.rb new file mode 100644 index 000000000..8d8ff6730 --- /dev/null +++ b/lib/liquid/template_recorder.rb @@ -0,0 +1,616 @@ +# frozen_string_literal: true + +require 'English' +require "digest/sha2" +require "json" +require "securerandom" +require "tempfile" +require "time" + +module Liquid + # Records complete Liquid renders without changing the objects being rendered. + # A .json file contains one session; a .jsonl file is an append-only sequence + # of independently replayable renders. + class TemplateRecorder + FORMAT = "liquid-render" + SCHEMA_VERSION = 1 + REGISTER_KEY = :__liquid_template_recorder + REPLAYER_REGISTER_KEY = :__liquid_template_recorder_replayer + + # Boot-time gate for the instrumentation hooks. + # + # The hooks sit on the hottest paths a host application has — every drop + # read, filter call, tag and variable — and a host that never records + # should not pay for them. Reading a false constant is the cheapest check + # available, and Storefront measured the ungated hooks at +1.59% + # allocations per request with recording switched off. + # + # This is deliberately boot-time rather than runtime: a constant is what + # makes the disabled path free. Recording is generated offline, so the + # processes that need it set this at boot and nothing else pays. + HOOKS_ENABLED = !ENV["LIQUID_TEMPLATE_RECORDER_HOOKS"].nil? + + # Opening tag markup, with or without whitespace control. + TAG_NAME_PATTERN = /\{%-?\s*(\w+)/ + + class Error < StandardError; end + class ReplayError < Error; end + class SerializationError < Error; end + + class << self + def record(destination, on_error: nil) + raise ArgumentError, "a block is required" unless block_given? + unless HOOKS_ENABLED + raise Error, "recording hooks are disabled; set LIQUID_TEMPLATE_RECORDER_HOOKS before boot" + end + + previous_session = current + raise Error, "nested recording sessions are not supported" if previous_session + + session = Session.new(destination, on_error: on_error) + Thread.current[thread_key] = session + yield + ensure + if session + Thread.current[thread_key] = previous_session + session.close if $ERROR_INFO.nil? + end + end + + def current + Thread.current[thread_key] + end + + def replay_from(path, mode: :compute, index: -1) + records = Store.read(path) + raise ReplayError, "recording contains no renders" if records.empty? + + record = records.fetch(index) + Replayer.new(record, mode: mode) + rescue IndexError + raise ReplayError, "render index #{index} does not exist" + end + + def records(path) + Store.read(path) + end + + private + + def thread_key + :__liquid_template_recorder_session + end + end + + class Session + def initialize(destination, on_error:) + @path = destination.to_s if destination.is_a?(String) || destination.respond_to?(:to_path) + @writer = destination unless @path + @on_error = on_error + @records = [] + @active = nil + @pending_files = {} + end + + def begin_render(template, _assigns, context) + if @active + @active.add_template(template) + @active.nesting += 1 + return @active + end + + @active = Render.new(template, context) + @pending_files.each { |path, source| @active.emit_file_read(path, source) } + @pending_files.clear + @active + end + + def emit_file_read(path, source) + if @active + @active.emit_file_read(path, source) + else + @pending_files[path.to_s] = source + end + end + + def emit_variable_output(output) + @active&.emit_variable_output(output) + end + + def begin_tag_render(node, context) + @active&.begin_tag_render(node, context) + end + + def finish_tag_render(call, output) + @active&.finish_tag_render(call, output) + end + + def finish_render(render, output, context, success:) + return unless render.equal?(@active) + + if render.nesting.positive? + render.nesting -= 1 + return + end + + if success + begin + record = render.finish(output, context) + if @writer + @writer.write(record) + elsif Store.jsonl?(@path) + Store.append(@path, record) + else + @records << record + end + rescue => error + handle_error(error) + end + end + @active = nil + end + + def close + return if @writer || Store.jsonl?(@path) + + Store.write_session(@path, @records) + rescue => error + handle_error(error) + end + + private + + def handle_error(error) + raise error unless @on_error + + @on_error.call(error) + end + end + + class Render + attr_accessor :nesting + + def initialize(template, _context) + @nesting = 0 + @templates = [] + @files = {} + @filter_calls = [] + @tag_calls = [] + @tag_render_depth = 0 + @variables = {} + @variable_outputs = [] + @drop_values = {} + @bindings = {}.compare_by_identity + @root_template = template + add_template(template) + end + + def add_template(template) + source = template.instance_variable_get(:@template_recorder_source) + return unless source + + entrypoint = template.name + digest = Digest::SHA256.hexdigest(source) + return if @templates.any? { |item| item["sha256"] == digest && item["entrypoint"] == entrypoint } + + @templates << { "source" => source, "entrypoint" => entrypoint, "sha256" => digest } + end + + def emit_variable_output(output) + return if @tag_render_depth.positive? + + @variable_outputs << output + end + + def begin_tag_render(node, context) + name = context.environment.tags.key(node.class) + return unless name + + @tag_render_depth += 1 + return :nested if @tag_render_depth > 1 + + call = { "name" => name.to_s, "output" => nil } + @tag_calls << call + call + end + + def finish_tag_render(call, output) + return unless call + + @tag_render_depth -= 1 + call["output"] = output unless call == :nested + end + + def emit_variable_read(name, value) + path = [name.to_s] + @variables[name.to_s] = serialize(value, path, bind: true) + rescue SerializationError + # Unsupported values must not affect the render being observed. + end + + def emit_drop_read(drop, key, value) + base = @bindings[drop] + return unless base + + path = base + [key.to_s] + set_path(@drop_values, path, serialize(value, path, bind: true)) + rescue SerializationError + # Unsupported values must not affect the render being observed. + end + + def emit_file_read(path, source) + @files[path.to_s] = source.to_s + end + + def emit_filter_call(name, input, arguments, output) + return if @tag_render_depth.positive? + + @filter_calls << { + "name" => name.to_s, + "input" => serialize(input, ["filters", @filter_calls.length, "input"]), + "arguments" => serialize(arguments, ["filters", @filter_calls.length, "arguments"]), + "output" => serialize(output, ["filters", @filter_calls.length, "output"]), + } + rescue SerializationError + # Filter diagnostics must never make an otherwise replayable render fail. + end + + def finish(output, context) + variables = deep_merge(@variables, @drop_values) + source = @root_template.instance_variable_get(:@template_recorder_source) + raise Error, "the rendered template was parsed outside the recording block" unless source + + { + "format" => FORMAT, + "schema_version" => SCHEMA_VERSION, + "id" => SecureRandom.uuid, + "recorded_at" => Time.now.utc.iso8601, + "engine" => { + "liquid_version" => Liquid::VERSION, + "ruby_version" => RUBY_VERSION, + "strict_variables" => !!context.strict_variables, + "strict_filters" => !!context.strict_filters, + }, + "template" => @templates.first, + "templates" => @templates, + "assigns" => variables, + "variable_outputs" => @variable_outputs, + "file_system" => @files, + "filter_calls" => @filter_calls, + "tag_calls" => @tag_calls, + "output" => output.to_s, + } + end + + private + + def serialize(value, path, seen = {}.compare_by_identity, bind: false) + case value + when nil, true, false, String, Integer, Float + value + when Symbol + value.to_s + when Liquid::Drop + @bindings[value] ||= path if bind + existing = value_at(@drop_values, @bindings[value]) + existing || {} + when Hash + raise SerializationError, "circular value at #{format_path(path)}" if seen.key?(value) + + seen[value] = true + result = value.each_with_object({}) do |(key, child), hash| + string_key = key.to_s + hash[string_key] = serialize(child, path + [string_key], seen, bind: bind) + end + seen.delete(value) + result + when Array + raise SerializationError, "circular value at #{format_path(path)}" if seen.key?(value) + + seen[value] = true + result = value.each_with_index.map { |child, index| serialize(child, path + [index], seen, bind: bind) } + seen.delete(value) + result + else + raise SerializationError, "cannot record #{value.class} at #{format_path(path)}" + end + end + + def set_path(root, path, value) + return root.replace(value) if path.empty? && value.is_a?(Hash) + + cursor = root + path.each_with_index do |segment, index| + last = index == path.length - 1 + if segment.is_a?(Integer) + break unless cursor.is_a?(Array) + + end + cursor[segment] = last ? value : (cursor[segment] ||= container_for(path[index + 1])) + cursor = cursor[segment] unless last + end + end + + def value_at(root, path) + return unless path + + path.reduce(root) { |value, segment| value.respond_to?(:[]) ? value[segment] : nil } + end + + def container_for(segment) + segment.is_a?(Integer) ? [] : {} + end + + def deep_merge(left, right) + return right unless left.is_a?(Hash) && right.is_a?(Hash) + + left.merge(right) { |_key, a, b| deep_merge(a, b) } + end + + def format_path(path) + path.empty? ? "" : path.join(".") + end + end + + class Store + class << self + def jsonl?(path) + path.end_with?(".jsonl") + end + + def append(path, record) + line = JSON.generate(record) << "\n" + File.open(path, File::WRONLY | File::CREAT | File::APPEND, 0o600) do |file| + file.flock(File::LOCK_EX) + file.write(line) + file.flush + end + end + + def write_session(path, records) + payload = JSON.pretty_generate( + "format" => "liquid-recording-session", + "schema_version" => SCHEMA_VERSION, + "renders" => records, + ) << "\n" + directory = File.dirname(File.expand_path(path)) + Tempfile.create([".liquid-recording", ".tmp"], directory, mode: File::RDWR, perm: 0o600) do |file| + file.write(payload) + file.flush + file.fsync + File.rename(file.path, path) + end + end + + def read(path) + content = File.binread(path) + records = if jsonl?(path) + read_jsonl(content) + else + parsed = JSON.parse(content) + parsed["renders"] || [parsed] + end + records.each { |record| validate!(record) } + records + rescue Errno::ENOENT + raise ReplayError, "recording file not found: #{path}" + rescue JSON::ParserError => error + raise ReplayError, "invalid recording JSON: #{error.message}" + end + + def read_jsonl(content) + lines = content.lines + lines.filter_map.with_index do |line, index| + next if line.strip.empty? + + JSON.parse(line) + rescue JSON::ParserError + last_truncated_line = index == lines.length - 1 && !content.end_with?("\n") + raise unless last_truncated_line + end + end + + def validate!(record) + raise ReplayError, "unsupported recording format" unless record["format"] == FORMAT + raise ReplayError, "unsupported schema version #{record["schema_version"].inspect}" unless record["schema_version"] == SCHEMA_VERSION + + ['template', 'assigns', 'file_system', 'output'].each do |key| + raise ReplayError, "recording is missing #{key}" unless record.key?(key) + end + template = record["template"] + expected = Digest::SHA256.hexdigest(template.fetch("source")) + raise ReplayError, "template checksum does not match" unless template["sha256"] == expected + rescue KeyError, TypeError => error + raise ReplayError, "invalid recording schema: #{error.message}" + end + end + end + + class MemoryFileSystem + def initialize(files) + @files = files + end + + def read_template_file(path) + @files.fetch(path.to_s) { raise FileSystemError, "No such template '#{path}'" } + end + end + + class Replayer + def initialize(record, mode: :compute, environment: nil) + @record = record + @mode = mode.to_sym + @environment = environment + unless [:compute, :strict, :verify].include?(@mode) + raise ReplayError, "mode must be :compute, :strict, or :verify" + end + end + + def render(to: nil, filters: nil) + @filter_index = 0 + @tag_index = 0 + @variable_index = 0 + parse_options = {} + parse_options[:environment] = strict_environment if @mode == :strict + template = Liquid::Template.parse(@record.dig("template", "source"), parse_options) + registers = { file_system: MemoryFileSystem.new(@record["file_system"]) } + registers[REPLAYER_REGISTER_KEY] = self if @mode == :strict && @record.key?("variable_outputs") + options = { + registers: registers, + strict_variables: @record.dig("engine", "strict_variables"), + strict_filters: @record.dig("engine", "strict_filters"), + } + options[:filters] = filters if filters + output = template.render!(@record["assigns"], options) + if @mode == :strict + verify_filter_count! unless @record.key?("variable_outputs") + verify_tag_count! + verify_variable_count! + end + if [:strict, :verify].include?(@mode) && output != @record["output"] + raise ReplayError, "replayed output does not match the recording" + end + + File.binwrite(to, output) if to + output + end + + def replay_filter(name) + call = @record["filter_calls"].fetch(@filter_index) do + raise ReplayError, "unexpected filter call #{name}" + end + if call["name"] != name.to_s + raise ReplayError, "expected filter #{call["name"]}, got #{name}" + end + + @filter_index += 1 + JSON.parse(JSON.generate(call["output"])) + end + + def replay_variable + value = @record.fetch("variable_outputs").fetch(@variable_index) do + raise ReplayError, "unexpected variable render" + end + @variable_index += 1 + value + end + + def replay_tag(name) + call = @record.fetch("tag_calls", []).fetch(@tag_index) do + raise ReplayError, "unexpected tag call #{name}" + end + if call["name"] != name.to_s + raise ReplayError, "expected tag #{call["name"]}, got #{name}" + end + + @tag_index += 1 + call["output"] + end + + def recorded_output + @record["output"] + end + + def templates + @record["templates"] + end + + private + + def strict_environment + replayer = self + strainer = Class.new(Liquid::StrainerTemplate) do + define_method(:invoke) do |name, *_args| + replayer.replay_filter(name) + end + end + tags = (@environment || Liquid::Environment.default).tags.dup + tags&.each do |name, tag_class| + tags[name] = replay_tag_class(tag_class, name) + end + register_host_tag_stubs(tags) + Liquid::Environment.build(tags: tags) do |environment| + environment.strainer_template = strainer + end + end + + # Registers a stub for every tag the recorded sources mention that this + # environment does not know. + # + # A recording taken inside a host application names that application's + # tags, and strict replay re-parses the recorded source. Without a stub + # the parse fails and the recording is replayable only inside the + # application it came from, which defeats the point of recording it. + # + # A stub is only ever parsed. A tag that was invoked has its recorded + # output substituted by +replay_tag_class+; a block stub consumes its + # body without rendering it, so a custom tag nested inside another one + # never executes and never consumes a recorded call. + def register_host_tag_stubs(tags) + names, blocks = host_tag_names(tags) + + names.each do |name| + stub = blocks.include?(name) ? Liquid::Block : Liquid::Tag + tags[name] = replay_tag_class(Class.new(stub), name) + end + end + + # Unknown tag names in every recorded source, and which of them are + # closed by a matching +end+ tag and so must parse as blocks. + def host_tag_names(known) + names = [] + blocks = [] + + recorded_sources.each do |source| + source.scan(TAG_NAME_PATTERN) do |(name)| + if name.start_with?("end") + blocks << name.delete_prefix("end") + elsif !known.key?(name) && !names.include?(name) + names << name + end + end + end + + [names, blocks] + end + + def recorded_sources + sources = Array(@record["templates"]).filter_map { |template| template["source"] } + sources.concat(Array(@record["file_system"]&.values)) + sources.compact + end + + def replay_tag_class(tag_class, name) + replayer = self + Class.new(tag_class) do + define_method(:render_to_output_buffer) do |_context, output| + output << replayer.replay_tag(name) + end + end + end + + def verify_variable_count! + return unless @record.key?("variable_outputs") + + expected = @record["variable_outputs"].length + return if @variable_index == expected + + raise ReplayError, "expected #{expected} variable renders, got #{@variable_index}" + end + + def verify_tag_count! + expected = @record.fetch("tag_calls", []).length + return if @tag_index == expected + + raise ReplayError, "expected #{expected} tag calls, got #{@tag_index}" + end + + def verify_filter_count! + expected = @record["filter_calls"].length + return if @filter_index == expected + + raise ReplayError, "expected #{expected} filter calls, got #{@filter_index}" + end + end + end +end diff --git a/lib/liquid/variable.rb b/lib/liquid/variable.rb index 12b8d9f28..879140db0 100644 --- a/lib/liquid/variable.rb +++ b/lib/liquid/variable.rb @@ -109,8 +109,14 @@ def render(context) end def render_to_output_buffer(context, output) + if TemplateRecorder::HOOKS_ENABLED && (replayer = context.registers[TemplateRecorder::REPLAYER_REGISTER_KEY]) + return output << replayer.replay_variable + end + + output_start = output.length obj = render(context) render_obj_to_output(obj, output) + TemplateRecorder.current&.emit_variable_output(output[output_start..]) if TemplateRecorder::HOOKS_ENABLED output end diff --git a/test/integration/template_recorder_disabled_test.rb b/test/integration/template_recorder_disabled_test.rb new file mode 100644 index 000000000..19f5158c6 --- /dev/null +++ b/test/integration/template_recorder_disabled_test.rb @@ -0,0 +1,15 @@ +# frozen_string_literal: true + +require_relative "../test_helper" + +class TemplateRecorderDisabledTest < Minitest::Test + def test_recording_fails_loudly_when_hooks_are_disabled + skip if Liquid::TemplateRecorder::HOOKS_ENABLED + + error = assert_raises(Liquid::TemplateRecorder::Error) do + Liquid::TemplateRecorder.record(Object.new) { flunk } + end + + assert_match("set LIQUID_TEMPLATE_RECORDER_HOOKS before boot", error.message) + end +end diff --git a/test/integration/template_recorder_test.rb b/test/integration/template_recorder_test.rb new file mode 100644 index 000000000..507ba33d8 --- /dev/null +++ b/test/integration/template_recorder_test.rb @@ -0,0 +1,414 @@ +# frozen_string_literal: true + +require_relative "../test_helper" +require "tmpdir" + +class TemplateRecorderTest < Minitest::Test + class ProductDrop < Liquid::Drop + def initialize(title, secret) + super() + @title = title + @secret = secret + end + + attr_reader :title + + def details + DetailsDrop.new + end + end + + class DetailsDrop < Liquid::Drop + def count + 3 + end + end + + class LegacyFileSystem + attr_reader :reads + + def initialize + @reads = [] + end + + def read_template_file(name) + @reads << name + "partial={{ product.title }}" + end + end + + class UnsupportedLiquidValue + def to_liquid + self + end + + def to_s + "unsupported" + end + end + + class WrapperTag < Liquid::Block + end + + class MarkerTag < Liquid::Tag + def render(_context) + "custom" + end + end + + class CollectingWriter + attr_reader :records + + def initialize + @records = [] + end + + def write(record) + @records << record + end + end + + def setup + @directory = Dir.mktmpdir + end + + def teardown + FileUtils.remove_entry(@directory) + end + + def path(name = "recording.json") + File.join(@directory, name) + end + + def test_records_and_verifies_a_render_without_changing_drop_behavior + product = ProductDrop.new("Computed", "must not be recorded") + template_source = "{{ product.title }} ({{ product.details.count }})" + + output = Liquid::TemplateRecorder.record(path) do + Liquid::Template.parse(template_source).render!("product" => product) + end + + assert_equal("Computed (3)", output) + record = Liquid::TemplateRecorder.records(path).first + assert_equal({ "title" => "Computed", "details" => { "count" => 3 } }, record.dig("assigns", "product")) + refute_includes(File.read(path), "must not be recorded") + assert_equal(output, Liquid::TemplateRecorder.replay_from(path, mode: :verify).render) + end + + def test_preserves_the_legacy_one_argument_file_system_contract + file_system = LegacyFileSystem.new + environment = Liquid::Environment.build { |env| env.file_system = file_system } + + output = Liquid::TemplateRecorder.record(path) do + Liquid::Template.parse("before {% include 'card' %}", environment: environment) + .render!("product" => ProductDrop.new("Hat", "secret")) + end + + assert_equal("before partial=Hat", output) + assert_equal(["card"], file_system.reads) + record = Liquid::TemplateRecorder.records(path).first + assert_equal({ "card" => "partial={{ product.title }}" }, record["file_system"]) + assert_equal(2, record["templates"].length) + assert_equal(output, Liquid::TemplateRecorder.replay_from(path, mode: :verify).render) + end + + def test_jsonl_appends_one_self_contained_record_per_render + recording = path("renders.jsonl") + + 2.times do |sequence| + Liquid::TemplateRecorder.record(recording) do + Liquid::Template.parse("value={{ value }}").render!("value" => sequence) + end + end + + assert_equal(2, File.readlines(recording).length) + assert_equal(["value=0", "value=1"], Liquid::TemplateRecorder.records(recording).map { |item| item["output"] }) + assert_equal("value=0", Liquid::TemplateRecorder.replay_from(recording, index: 0).render) + assert_equal("value=1", Liquid::TemplateRecorder.replay_from(recording).render) + end + + def test_json_session_supports_multiple_renders + Liquid::TemplateRecorder.record(path) do + Liquid::Template.parse("one={{ value }}").render!("value" => 1) + Liquid::Template.new.parse("two={{ value }}").render!("value" => 2) + end + + records = Liquid::TemplateRecorder.records(path) + assert_equal(["one=1", "two=2"], records.map { |item| item["output"] }) + assert_equal("two=2", Liquid::TemplateRecorder.replay_from(path).render) + end + + def test_failed_recording_does_not_delete_an_existing_json_file + File.write(path, "existing") + + assert_raises(RuntimeError) do + Liquid::TemplateRecorder.record(path) { raise "boom" } + end + + assert_equal("existing", File.read(path)) + end + + def test_render_failure_is_not_written_to_jsonl + recording = path("renders.jsonl") + + assert_raises(Liquid::UndefinedVariable) do + Liquid::TemplateRecorder.record(recording) do + Liquid::Template.parse("{{ missing }}").render!(nil, strict_variables: true) + end + end + + refute_path_exists(recording) + end + + def test_memory_limited_render_is_not_recorded_as_successful + writer = CollectingWriter.new + template = Liquid::Template.parse("0123456789") + template.resource_limits.render_length_limit = 9 + + output = Liquid::TemplateRecorder.record(writer) { template.render } + + assert_equal("Liquid error: Memory limits exceeded", output) + assert_empty(writer.records) + end + + def test_tampered_template_is_rejected + Liquid::TemplateRecorder.record(path) { Liquid::Template.parse("safe").render! } + session = JSON.parse(File.read(path)) + session["renders"][0]["template"]["source"] = "changed" + File.write(path, JSON.generate(session)) + + error = assert_raises(Liquid::TemplateRecorder::ReplayError) do + Liquid::TemplateRecorder.replay_from(path) + end + assert_match(/checksum/, error.message) + end + + def test_recordings_are_thread_local + paths = [path("a.json"), path("b.json")] + ready = Queue.new + release = Queue.new + threads = Array.new(2) do |index| + Thread.new do + Liquid::TemplateRecorder.record(paths[index]) do + ready << true + release.pop + Liquid::Template.parse("thread={{ value }}").render!("value" => index) + end + end + end + 2.times { ready.pop } + 2.times { release << true } + threads.each(&:join) + + assert_equal("thread=0", Liquid::TemplateRecorder.records(paths[0]).first["output"]) + assert_equal("thread=1", Liquid::TemplateRecorder.records(paths[1]).first["output"]) + end + + def test_nested_sessions_fail_without_corrupting_outer_session + error = nil + Liquid::TemplateRecorder.record(path) do + error = assert_raises(Liquid::TemplateRecorder::Error) do + Liquid::TemplateRecorder.record(path("inner.json")) { flunk } + end + Liquid::Template.parse("outer").render! + end + + assert_match(/nested/, error.message) + assert_equal("outer", Liquid::TemplateRecorder.replay_from(path).render) + end + + def test_supported_render_argument_forms_keep_working + filter = Module.new do + def decorate(input) + "[#{input}]" + end + end + template = nil + context = Liquid::Context.new([{ "value" => "context" }]) + + Liquid::TemplateRecorder.record(path) do + template = Liquid::Template.parse("{{ value | decorate }}") + assert_equal("[hash]", template.render({ "value" => "hash" }, filter)) + context.add_filters(filter) + assert_equal("[context]", template.render(context)) + end + + assert_equal(2, Liquid::TemplateRecorder.records(path).length) + end + + def test_strict_replay_uses_exact_recorded_filter_outputs + filter = Module.new do + def external_lookup(_input) + "x" * 150 + end + end + + output = Liquid::TemplateRecorder.record(path) do + Liquid::Template.parse("{{ key | external_lookup }}").render!({ "key" => "a" }, filter) + end + + assert_equal("x" * 150, output) + assert_equal(output, Liquid::TemplateRecorder.replay_from(path, mode: :strict).render) + assert_equal("a", Liquid::TemplateRecorder.replay_from(path, mode: :compute).render) + end + + def test_jsonl_reader_ignores_only_a_truncated_final_record + recording = path("renders.jsonl") + Liquid::TemplateRecorder.record(recording) { Liquid::Template.parse("complete").render! } + File.open(recording, "ab") { |file| file.write('{"format":') } + + assert_equal(["complete"], Liquid::TemplateRecorder.records(recording).map { |item| item["output"] }) + end + + def test_accepts_a_pluggable_writer + writer = CollectingWriter.new + + output = Liquid::TemplateRecorder.record(writer) do + Liquid::Template.parse("Hello {{ name }}").render!("name" => "Shopify") + end + + assert_equal("Hello Shopify", output) + assert_equal(["Hello Shopify"], writer.records.map { |record| record["output"] }) + end + + def test_records_only_variables_resolved_by_the_template + unused = Object.new + assigns = { "visible" => "yes", "unused" => unused } + + Liquid::TemplateRecorder.record(path) do + Liquid::Template.parse("{{ visible }}").render!(assigns) + end + + assert_equal({ "visible" => "yes" }, Liquid::TemplateRecorder.records(path).first["assigns"]) + end + + def test_recording_scope_is_fiber_local + writer = CollectingWriter.new + ordinary_output = nil + + Liquid::TemplateRecorder.record(writer) do + Fiber.new do + ordinary_output = Liquid::Template.parse("ordinary").render! + end.resume + Liquid::Template.parse("recorded").render! + end + + assert_equal("ordinary", ordinary_output) + assert_equal(["recorded"], writer.records.map { |record| record["output"] }) + end + + def test_on_error_keeps_recording_failures_out_of_the_render_path + writer = Object.new + writer.define_singleton_method(:write) { |_record| raise "sink unavailable" } + errors = [] + + output = Liquid::TemplateRecorder.record(writer, on_error: errors.method(:<<)) do + Liquid::Template.parse("still rendered").render! + end + + assert_equal("still rendered", output) + assert_equal(["sink unavailable"], errors.map(&:message)) + end + + def test_unsupported_accessed_values_do_not_affect_the_render + value = UnsupportedLiquidValue.new + writer = CollectingWriter.new + + output = Liquid::TemplateRecorder.record(writer) do + Liquid::Template.parse("{{ value }}").render!("value" => value) + end + + assert_equal(value.to_s, output) + assert_equal({}, writer.records.first["assigns"]) + end + + def test_recorder_hooks_accept_host_application_contexts + product = ProductDrop.new("Computed", "secret") + product.context = Object.new + assert_equal("Computed", product.invoke_drop("title")) + + filter = Module.new do + def passthrough(input) + input + end + end + strainer_class = Class.new(Liquid::StrainerTemplate) + strainer_class.add_filter(filter) + + assert_equal("value", strainer_class.new(Object.new).invoke(:passthrough, "value")) + end + + def test_records_only_output_produced_by_the_template + writer = CollectingWriter.new + output = +"prefix:" + + Liquid::TemplateRecorder.record(writer) do + Liquid::Template.parse("body").render!({}, output: output) + output << ":suffix" + end + + assert_equal("prefix:body:suffix", output) + assert_equal("body", writer.records.first["output"]) + end + + def test_strict_replay_accepts_the_application_environment + environment = Liquid::Environment.build( + tags: Liquid::Environment.default.tags.merge("marker" => MarkerTag), + ) + writer = CollectingWriter.new + Liquid::TemplateRecorder.record(writer) do + Liquid::Template.parse("{% marker %}", environment: environment).render! + end + + replay = Liquid::TemplateRecorder::Replayer.new( + writer.records.first, + mode: :strict, + environment: environment, + ) + + assert_equal("custom", replay.render) + end + + def test_strict_replay_stubs_host_application_tags + environment = Liquid::Environment.build( + tags: Liquid::Environment.default.tags.merge("wrapper" => WrapperTag, "marker" => MarkerTag), + ) + writer = CollectingWriter.new + Liquid::TemplateRecorder.record(writer) do + Liquid::Template.parse("{% wrapper %}{% marker %}{% endwrapper %}", environment: environment).render! + end + + replay = Liquid::TemplateRecorder::Replayer.new(writer.records.first, mode: :strict) + + assert_equal("custom", replay.render) + end + + def test_captures_file_reads_that_happen_before_the_template_starts_rendering + writer = CollectingWriter.new + Liquid::TemplateRecorder.record(writer) do + Liquid::TemplateRecorder.current.emit_file_read("card", "Card") + file_system = LegacyFileSystem.new + Liquid::Template.parse("{% render 'card' %}").render!({}, registers: { file_system: file_system }) + end + + replay = Liquid::TemplateRecorder::Replayer.new(writer.records.first, mode: :strict) + + assert_equal("partial=", replay.render) + end + + def test_strict_replay_skips_nested_custom_tag_calls + environment = Liquid::Environment.build( + tags: Liquid::Environment.default.tags.merge("wrapper" => WrapperTag, "marker" => MarkerTag), + ) + writer = CollectingWriter.new + Liquid::TemplateRecorder.record(writer) do + Liquid::Template.parse("{% wrapper %}{% marker %}{% endwrapper %}", environment: environment).render! + end + + record = writer.records.first + replay = Liquid::TemplateRecorder::Replayer.new(record, mode: :strict, environment: environment) + + assert_equal(["wrapper"], record["tag_calls"].map { |call| call["name"] }) + assert_equal("custom", replay.render) + end +end