Strange character in WEBrick output - LogTailer gets out of sync with log file

There's is a 's' character after '...Completed 302 Found in 73ms'. I'm getting this character every time I create/update a record. Is this somehow related to "_snowman"=>"☃" ?

Started POST "/tasks/1" for 127.0.0.1 at 2010-07-27 18:35:00 -0400
  Processing by TasksController#update as HTML
  Parameters: {"_snowman"=>"☃", "authenticity_token"=>"iOLKcwhiDDQahpPIWV3Grv1XmA0PZ0JmNMQfKshFtp4=", "task"=>{"name"=>"task 1"}, "commit"=>"Update Task", "id"=>"1"}
  Task Load (0.1ms)  SELECT "tasks".* FROM "tasks" WHERE ("tasks"."id" = 1) LIMIT 1
  SQL (0.2ms)  UPDATE "tasks" SET "name" = 'task 1', "updated_at" = '2010-07-27 22:35:00.576330' WHERE ("tasks"."id" = 1)
Redirected to http://localhost:3008/tasks/1
Completed 302 Found in 73ms
s


Started GET "/tasks/1" for 127.0.0.1 at 2010-07-27 18:35:00 -0400
  Processing by TasksController#show as HTML
  Parameters: {"id"=>"1"}
  Task Load (0.1ms)  SELECT "tasks".* FROM "tasks" WHERE ("tasks"."id" = 1) LIMIT 1
Rendered tasks/show.html.erb within layouts/application (6.8ms)
Completed 200 OK in 18ms (Views: 9.4ms | ActiveRecord: 0.1ms)

Like if you would write @@@puts 's'@@@ in your rails app.

Sorry, I didn't know what I was thinking :P

Yes, I confirm that after a post, the last character of the process_action method is printed again when you execute another action, probably something related to the buffer or something like that

So i.e. if you update ActionController::LogSubscriber#process_action

      #message = "Completed #{payload[:status]} #{Rack::Utils::HTTP_STATUS_CODES[payload[:status]]} in %.0fms" % event.duration
      #message << " (#{additions.join(" | ")})" unless additions.blank?
      message = 'hello world'

you will see a 'd' instead of a 's'

It happens with webrick on the console, the logs file doesn't seem affected by it

All create/update requests. Small application attached. I'm using Ruby 1.9.2dev.

It's something related to the bufferered logger and webrick.

The same logger writes the content as expected on the log files, but it adds the last character of the post messaged logged by LogSubscriber#process_action.

But another thing it's happening on my rails applications (ruby 1.9.2.RC and master branch of rails), is that on a create action (POST request followed by a GET request because of redirection), the POST action is being shown in the webrick console, but the GET request is not being displayed, and after that, if you do any other request, then the GET request that was not shown is shown and here is where the character appears.

So, after calling the create action, I see this on the webrick console

Started POST "/projects" for 127.0.0.1 at 2010-07-28 02:04:46 -0300
  Processing by ProjectsController#create as HTML
  Parameters: {"_snowman"=>"☃", "authenticity_token"=>"MQlcfwwQiI3xlnjKWx40iW+bx4pxi+Esc8jLNByuDaw=", "project"=>{"name"=>"a", "title"=>"b", "description"=>"c", "start_on(1i)"=>"2010", "start_on(2i)"=>"7", "start_on(3i)"=>"28", "end_on(1i)"=>"2010", "end_on(2i)"=>"7", "end_on(3i)"=>"28"}, "commit"=>"Create Project"}
  SQL (0.3ms)  BEGIN
  SQL (0.4ms)  INSERT INTO projects (created_at, description, end_on, name, start_on, title, updated_at) VALUES ('2010-07-28 05:04:46', 'c', '2010-07-28', 'a', '2010-07-28', 'b', '2010-07-28 05:04:46')
  SQL (1.3ms)  COMMIT
Redirected to http://localhost:3000/projects/27
Completed 302 Found in 34ms

And then if I go to any page, like to projects/27

s







Started GET "/projects/27" for 127.0.0.1 at 2010-07-28 02:04:46 -0300
  Processing by ProjectsController#show as HTML
  Parameters: {"id"=>"27"}
  Project Load (1.2ms)  SELECT projects.* FROM projects WHERE (projects.id = 27) LIMIT 1
Rendered projects/show.html.erb within layouts/application (18.6ms)
Completed 200 OK in 38ms (Views: 22.8ms | ActiveRecord: 3.1ms)



Started GET "/projects/27" for 127.0.0.1 at 2010-07-28 02:05:32 -0300
  Processing by ProjectsController#show as HTML
  Parameters: {"id"=>"27"}
  Project Load (1.2ms)  SELECT projects.* FROM projects WHERE (projects.id = 27) LIMIT 1
Rendered projects/show.html.erb within layouts/application (15.5ms)
Completed 200 OK in 37ms (Views: 20.8ms | ActiveRecord: 1.2ms)

So here you see that the first character appears, and that the GET action that was missing from when I created the model also appears.

Where the expected log on the console after saving the model should be

Started POST "/projects" for 127.0.0.1 at 2010-07-28 02:04:46 -0300
  Processing by ProjectsController#create as HTML
  Parameters: {"_snowman"=>"☃", "authenticity_token"=>"MQlcfwwQiI3xlnjKWx40iW+bx4pxi+Esc8jLNByuDaw=", "project"=>{"name"=>"a", "title"=>"b", "description"=>"c", "start_on(1i)"=>"2010", "start_on(2i)"=>"7", "start_on(3i)"=>"28", "end_on(1i)"=>"2010", "end_on(2i)"=>"7", "end_on(3i)"=>"28"}, "commit"=>"Create Project"}
  SQL (0.3ms)  BEGIN
  SQL (0.4ms)  INSERT INTO `projects` (`created_at`, `description`, `end_on`, `name`, `start_on`, `title`, `updated_at`) VALUES ('2010-07-28 05:04:46', 'c', '2010-07-28', 'a', '2010-07-28', 'b', '2010-07-28 05:04:46')
  SQL (1.3ms)  COMMIT
Redirected to http://localhost:3000/projects/27
Completed 302 Found in 34ms

Started GET "/projects/27" for 127.0.0.1 at 2010-07-28 02:04:46 -0300
  Processing by ProjectsController#show as HTML
  Parameters: {"id"=>"27"}
  Project Load (1.2ms)  SELECT `projects`.* FROM `projects` WHERE (`projects`.`id` = 27) LIMIT 1
Rendered projects/show.html.erb within layouts/application (18.6ms)
Completed 200 OK in 38ms (Views: 22.8ms | ActiveRecord: 3.1ms)

BTW, I'm using webrick 1.3.1

Curtis, nice, I tried your fix and works great for me :)

Curtis can you add a test for this?

Santiago, LogTailer doesn't have any tests currently.