fig logs not in real time

[zedtux]

When executing fig run or fig logs we can see the logs from all the contains (which is an awesome feature!).

I have a Rails containers where is running my application. The application works really well but there is no logs until there is an issue where the logs are refreshed, often.

I mean when I go to the homepage, I'm expecting to see an update in the logs window like the following:

web_1        | Started GET "/" for 192.168.59.3 at 2014-08-30 18:01:03 +0000
web_1        | Processing by WelcomeController#index as HTML
web_1        |   User Load (0.5ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = 1  ORDER BY "users"."id" ASC LIMIT 1
web_1        |   Rendered welcome/index.html.slim within layouts/application (0.2ms)
web_1        |   Rendered shared/_left_menu.html.slim (1.4ms)
web_1        | Completed 200 OK in 118ms (Views: 112.4ms | ActiveRecord: 0.5ms)

Is this normal that the logs window is not refreshed in realtime (like with the tail -f command on Linux) ?

[dnephin]

I was not able to reproduce this. When I tried this out with a minimal example I was seeing logs tail, just like tail -f.

[zedtux]

Right. Let me build an image on a registry and let's see what's wrong :)

[zedtux]

@dnephin I have an example for you.

You can try with my brewformulas.org project:

• by cloning from the Github repository and do fig up and fig run web bundle exec rake db:create db:migrate RAILS_ENV=production
• by pulling the image from Quay.io

Let me know if I can do whatever to help!

[dnephin]

I pulled down the image from quay.io, and used it with the fig.yml from the git repo (except I changed the web from a build to image using the quay.io image).

I ran:

fig up -d
fig logs

Then hit localhost:3000.

Edit: oops, I missed some steps, let me try this again.

In your case is there something else that is tailing in realtime instead of the web_1 host? Are you running fig logs web or just fig logs ?

[dnephin]

Ok, so I did the steps correctly this time, and I am seeing the logs tail in realtime like tail -f, but I had to make a small change to the fig.yml. It seems that in production mode rails is not actually displaying the logs (I verified by running it interactively, there are no logs from rails). If I remove -e production it works just fine.

Are you sure that you aren't expecting logs that don't exist?

[zedtux]

Thank you for your investigations.

In your case is there something else that is tailing in realtime instead of the web_1 host?

Nope. I have only an image for Postgres (which is tailing in realtime) with the following output only on start:

postgresql_1 | LOG:  database system was shut down at 2014-08-31 17:57:07 UTC
postgresql_1 | LOG:  database system is ready to accept connections
postgresql_1 | LOG:  autovacuum launcher started

Are you running fig logs web or just fig logs ?

I'm running only fig logs.

Are you sure that you aren't expecting logs that don't exist?

Yes I am as my reported issue is about logs not being refreshed often enough.

Now what I have tried meanwhile, is to force the Rails logger to log in the stdout instead of the logs/development.log file. (Rails is logging in the stdout of the server plus in the log file by default. And I'm expecting to see those logs from the rails server). In order to achieve this, what I did is to add the rails_stdout_logging gem to my Gemfile so that my application is only logging to the stdout. Since this is installed, I see in realtime the logs from my server, but in double:

web_1        | Started GET "/users/sign_in" for 192.168.59.3 at 2014-08-31 18:00:04 +0000
web_1        | Started GET "/users/sign_in" for 192.168.59.3 at 2014-08-31 18:00:04 +0000
web_1        |   ActiveRecord::SchemaMigration Load (0.5ms)  SELECT "schema_migrations".* FROM "schema_migrations"
web_1        |   ActiveRecord::SchemaMigration Load (0.5ms)  SELECT "schema_migrations".* FROM "schema_migrations"
web_1        | Processing by Devise::SessionsController#new as HTML
web_1        | Processing by Devise::SessionsController#new as HTML
web_1        |   Rendered devise/sessions/new.html.slim within layouts/application (195.9ms)
web_1        |   Rendered devise/sessions/new.html.slim within layouts/application (195.9ms)
web_1        |   User Exists (0.9ms)  SELECT  1 AS one FROM "users" LEFT OUTER JOIN "roles" ON "roles"."id" = "users"."role_id" WHERE "roles"."name" = 'admin' LIMIT 1
web_1        |   User Exists (0.9ms)  SELECT  1 AS one FROM "users" LEFT OUTER JOIN "roles" ON "roles"."id" = "users"."role_id" WHERE "roles"."name" = 'admin' LIMIT 1
web_1        |   Rendered shared/_testing_tools.html.slim (54.2ms)
web_1        |   Rendered shared/_testing_tools.html.slim (54.2ms)
web_1        |   User Load (0.7ms)  SELECT "users".* FROM "users" INNER JOIN "jobs" ON "users"."id" = "jobs"."user_id" WHERE "jobs"."position_id" = 3 AND "jobs"."hirable_id" = $1 AND "jobs"."hirable_type" = $2  [["hirable_id", 1], ["hirable_type", "School"]]
web_1        |   User Load (0.7ms)  SELECT "users".* FROM "users" INNER JOIN "jobs" ON "users"."id" = "jobs"."user_id" WHERE "jobs"."position_id" = 3 AND "jobs"."hirable_id" = $1 AND "jobs"."hirable_type" = $2  [["hirable_id", 1], ["hirable_type", "School"]]
web_1        |   Rendered shared/_testing_tools_modals.html.slim (94.4ms)
web_1        |   Rendered shared/_testing_tools_modals.html.slim (94.4ms)
web_1        | Completed 200 OK in 735ms (Views: 687.5ms | ActiveRecord: 13.2ms)
web_1        | Completed 200 OK in 735ms (Views: 687.5ms | ActiveRecord: 13.2ms)

This is normal as the server itself is printing to the stdout plus the application.

To summarise:

• Postgres image is tailing in realtime => Perfect
• Rails server is tailing only in some cases, so not in realtime
• Adding the gem in order to log everything in the stdout makes the Rails server tailing in realtime but in double

(I can do a video of what I have if it can help to understand)

I'm now wondering why is this happening...

[dnephin]

As a way to debug what is happening, I would try running interactively with fig run web, and see what logs you get there. If you don't see logs interactively , you won't see them in fig logs.

So far I haven't been able to reproduce the issue.

[zedtux]

So far I haven't been able to reproduce the issue.

You mean you've done the fig up and going to a page or another was tailing in the fig logs ?

[zedtux]

By the way, I'm using OS X Yosemite Beta 2, with iterm2, Docker 1.2.0, boot2docker v1.2.0, VirtualBox 4.3.14 and fig 0.5.2.

[dnephin]

Yes, it was tailing the logs when I removed -e production from the command. With -e production I didn't see any logs in the interactive run, so there was nothing to tail.

I was using fig master, but I don't think there have been any changes to this since the 0.5.2 release. docker 1.1.2 on linux (no boot2docker or virtualbox)

[zedtux]

Well that's wired as on another project I'm using the development environment (default one when you remove the -e production) and I had the same behaviour.

I will then give a try on Linux.

[jpanganiban]

@zedtux I don't know if this might help, but, have you tried adding $stdout.sync = true in your configuration. See basecamp/pow#356

I have the same issue. I'm working with Python. print doesn't seem to work with $ fig up.

I'm working with Fig 0.5.2 and Docker 1.1.1

[EDIT]: Logging with the logging module works.

[zedtux]

I will give it a try, thank you.

On my side, a colleague with Mavericks is not impacted by this issue. Maybe it's a Yosemite bug.

[bfirsh]

@jpanganiban On Python you need to set the PYTHONUNBUFFERED environment variable to stop stdout buffering - e.g. PYTHONUNBUFFERED=1

[jpanganiban]

@bfirsh: Thanks man! Works great! :+1:

[macropin]

I can confirm this is a stdout buffering issue. Issuing a sys.stdout.flush() in my script worked. However I still have issues with starting 3rd party containers with daemons that don't flush stdout.

[macropin]

This patch https://github.com/d11wtq/dockerpty/pull/6 works for me in resolving this issue. So I believe this is an upstream issue with dockerpty and can be closed here.

[dnephin]

This should be resolved now.