Excessive log after installation and deinstallation. Production.log is flooded by time_logger

[ppoektos]

Redmine 3.3.0.stable.15842
Environment:
  Redmine version                3.3.0.stable.15842
  Ruby version                   1.9.3-p327 (2012-11-10) [i686-linux]
  Rails version                  4.2.7.1
  Environment                    production
  Database adapter               Mysql2
SCM:
  Subversion                     1.8.8
  Git                            1.7.1
  Filesystem                     
Redmine plugins:
  advanced_roadmap_v2            2.4.3
  redmine_agile                  1.4.1
  redmine_checklists             3.1.5
  redmine_lightbox2              0.3.1
  redmine_timesheet_plugin       0.7.0
  redmine_xls_export             0.2.1.t9

Since I installed plugin it constantly writes to log few records per one minutes even in the night when nobody works:

Started GET "/time_loggers/render_menu?_=1474369321095" for 127.0.0.1 at 2016-09-20 13:21:59 +0200
Processing by TimeLoggersController#render_menu as */*
  Parameters: {"_"=>"1474369321095"}
  Current user: xxx (id=95)
  Rendered plugins/time_logger/app/views/time_loggers/_embed_menu.html.erb (50.7ms)
Completed 200 OK in 62ms (Views: 44.4ms | ActiveRecord: 9.9ms)
Started GET "/time_loggers/render_menu?_=1474368534502" for 127.0.0.1 at 2016-09-20 13:22:00 +0200
Processing by TimeLoggersController#render_menu as */*
  Parameters: {"_"=>"1474368534502"}
  Current user: xxx (id=182)
  Rendered plugins/time_logger/app/views/time_loggers/_embed_menu.html.erb (96.5ms)
Completed 200 OK in 109ms (Views: 95.3ms | ActiveRecord: 7.3ms)
Started GET "/time_loggers/render_menu?project_id=281&issue_id=23202&_=1474370044620" for 127.0.0.1 at 2016-09-20 13:22:04 +0200
Processing by TimeLoggersController#render_menu as */*
  Parameters: {"project_id"=>"281", "issue_id"=>"23202", "_"=>"1474370044620"}
  Current user: xxx (id=17)
  Rendered plugins/time_logger/app/views/time_loggers/_embed_menu.html.erb (2.7ms)
Completed 200 OK in 12ms (Views: 2.9ms | ActiveRecord: 3.7ms)

So I uninstalled plugin but somehow (maybe because of cookies) now there are massive flood with errors:

Started GET "/time_loggers/render_menu?project_id=476&issue_id=23152&_=1474378542489" for 127.0.0.1 at 2016-09-21 08:39:49 +0200

ActionController::RoutingError (No route matches [GET] "/time_loggers/render_menu"):
  actionpack (4.2.7.1) lib/action_dispatch/middleware/debug_exceptions.rb:21:in `call'
  actionpack (4.2.7.1) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
  railties (4.2.7.1) lib/rails/rack/logger.rb:38:in `call_app'
  railties (4.2.7.1) lib/rails/rack/logger.rb:20:in `block in call'
  activesupport (4.2.7.1) lib/active_support/tagged_logging.rb:68:in `block in tagged'
  activesupport (4.2.7.1) lib/active_support/tagged_logging.rb:26:in `tagged'
  activesupport (4.2.7.1) lib/active_support/tagged_logging.rb:68:in `tagged'
  railties (4.2.7.1) lib/rails/rack/logger.rb:20:in `call'
  actionpack (4.2.7.1) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  rack (1.6.4) lib/rack/methodoverride.rb:22:in `call'
  rack (1.6.4) lib/rack/runtime.rb:18:in `call'
  activesupport (4.2.7.1) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
  actionpack (4.2.7.1) lib/action_dispatch/middleware/static.rb:120:in `call'
  rack (1.6.4) lib/rack/sendfile.rb:113:in `call'
  railties (4.2.7.1) lib/rails/engine.rb:518:in `call'
  railties (4.2.7.1) lib/rails/application.rb:165:in `call'
  railties (4.2.7.1) lib/rails/railtie.rb:194:in `public_send'
  railties (4.2.7.1) lib/rails/railtie.rb:194:in `method_missing'
  unicorn (4.5.0) lib/unicorn/http_server.rb:552:in `process_client'
  unicorn (4.5.0) lib/unicorn/http_server.rb:628:in `worker_loop'
  unicorn (4.5.0) lib/unicorn/http_server.rb:500:in `spawn_missing_workers'
  unicorn (4.5.0) lib/unicorn/http_server.rb:142:in `start'
  unicorn (4.5.0) bin/unicorn_rails:209:in `<top (required)>'
  /usr/local/rvm/gems/ruby-1.9.3-p327/bin/unicorn_rails:19:in `load'
  /usr/local/rvm/gems/ruby-1.9.3-p327/bin/unicorn_rails:19:in `<main>'
  /usr/local/rvm/gems/ruby-1.9.3-p327/bin/ruby_executable_hooks:15:in `eval'
  /usr/local/rvm/gems/ruby-1.9.3-p327/bin/ruby_executable_hooks:15:in `<main>'


Started GET "/time_loggers/render_menu?project_id=281&issue_id=23109&_=1474375728842" for 127.0.0.1 at 2016-09-21 08:39:51 +0200

ActionController::RoutingError (No route matches [GET] "/time_loggers/render_menu"):
  actionpack (4.2.7.1) lib/action_dispatch/middleware/debug_exceptions.rb:21:in `call'
  actionpack (4.2.7.1) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
  railties (4.2.7.1) lib/rails/rack/logger.rb:38:in `call_app'
  railties (4.2.7.1) lib/rails/rack/logger.rb:20:in `block in call'
  activesupport (4.2.7.1) lib/active_support/tagged_logging.rb:68:in `block in tagged'
  activesupport (4.2.7.1) lib/active_support/tagged_logging.rb:26:in `tagged'
  activesupport (4.2.7.1) lib/active_support/tagged_logging.rb:68:in `tagged'
  railties (4.2.7.1) lib/rails/rack/logger.rb:20:in `call'
  actionpack (4.2.7.1) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  rack (1.6.4) lib/rack/methodoverride.rb:22:in `call'
  rack (1.6.4) lib/rack/runtime.rb:18:in `call'
  activesupport (4.2.7.1) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
  actionpack (4.2.7.1) lib/action_dispatch/middleware/static.rb:120:in `call'
  rack (1.6.4) lib/rack/sendfile.rb:113:in `call'
  railties (4.2.7.1) lib/rails/engine.rb:518:in `call'
  railties (4.2.7.1) lib/rails/application.rb:165:in `call'
  railties (4.2.7.1) lib/rails/railtie.rb:194:in `public_send'
  railties (4.2.7.1) lib/rails/railtie.rb:194:in `method_missing'
  unicorn (4.5.0) lib/unicorn/http_server.rb:552:in `process_client'
  unicorn (4.5.0) lib/unicorn/http_server.rb:628:in `worker_loop'
  unicorn (4.5.0) lib/unicorn/http_server.rb:500:in `spawn_missing_workers'
  unicorn (4.5.0) lib/unicorn/http_server.rb:142:in `start'
  unicorn (4.5.0) bin/unicorn_rails:209:in `<top (required)>'
  /usr/local/rvm/gems/ruby-1.9.3-p327/bin/unicorn_rails:19:in `load'
  /usr/local/rvm/gems/ruby-1.9.3-p327/bin/unicorn_rails:19:in `<main>'
  /usr/local/rvm/gems/ruby-1.9.3-p327/bin/ruby_executable_hooks:15:in `eval'
  /usr/local/rvm/gems/ruby-1.9.3-p327/bin/ruby_executable_hooks:15:in `<main>'

[poxtihc]

Hi, i have de same problem..¿any idea?

[ppoektos]

I made config.log_level = :warn in additional_environment.rb and restarted redmine.

[poxtihc]

Same result..

ActionController::RoutingError (No route matches [GET] "/time_loggers/render_menu"):
actionpack (4.2.6) lib/action_dispatch/middleware/debug_exceptions.rb:21:in call' actionpack (4.2.6) lib/action_dispatch/middleware/show_exceptions.rb:30:in call'
railties (4.2.6) lib/rails/rack/logger.rb:38:in call_app' railties (4.2.6) lib/rails/rack/logger.rb:20:in block in call'
activesupport (4.2.6) lib/active_support/tagged_logging.rb:68:in block in tagged' activesupport (4.2.6) lib/active_support/tagged_logging.rb:26:in tagged'
activesupport (4.2.6) lib/active_support/tagged_logging.rb:68:in tagged' railties (4.2.6) lib/rails/rack/logger.rb:20:in call'
actionpack (4.2.6) lib/action_dispatch/middleware/request_id.rb:21:in call' rack (1.6.4) lib/rack/methodoverride.rb:22:in call'
rack (1.6.4) lib/rack/runtime.rb:18:in call' activesupport (4.2.6) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in call'
actionpack (4.2.6) lib/action_dispatch/middleware/static.rb:120:in call' rack (1.6.4) lib/rack/sendfile.rb:113:in call'
railties (4.2.6) lib/rails/engine.rb:518:in call' railties (4.2.6) lib/rails/application.rb:165:in call'
railties (4.2.6) lib/rails/railtie.rb:194:in public_send' railties (4.2.6) lib/rails/railtie.rb:194:in method_missing'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in process_request' /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:152:in accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113:in main_loop' /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in block (3 levels) in start_threads'
/usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'

[speedy32129]

I've tried to reproduce this an I can't but here's a couple of things you can do.

Did you remove the directory? ../plugins/time_logger
If the directory is still there remove it. Restart web server. Check to see if that fixed the issue.

It that doesn't fix it
Also run query against the database select * from schema_migrations where version like "%time_logger%" limit 0,25

If it exists delete it
delete from schema_migrations where version like "%time_logger%"

Restart Web server and check again.

[danaivehr]

Hi! Having such issue too. Furthermore, after re-installing the plugin log is flooding with succesful "render_menu" gets every moment, wich is not good too.

After some digging it appears that apache access_log is flooding with "GET /time_loggers/render_menu" from several IP's constantly. Seems like a problem on a client side.

Can't say if it's bacause of open tab in browser on client side or some other issue.

[speedy32129]

I finally have been able to reproduce the issue. I'll let you all know when I have an update.

[muriloht]

Hi, I'm also getting this log messages... and when it happens the "play, pause and stop" buttons don't appear... if I can help with something, please let me know

[danaivehr]

I just performed some investigations and think that the main issue is using setInterval() for updateTimeLoggerMenu which gets data from server. It causes constant GET requests even if user doesn't see timer (in a foreground browser tab left overnight, just for example). If we have, say, 20 users, they have 5 tabs open with issues, its like a 100 useless additional requests per minute.

I found some examples to get "Tab is visible" property (see "Using the PageVisibility API" topic on html5rocks) and managed to apply them to logger. The main idia is to setIntervar when tab is visible and clear it otherwise. Code looks like this:

  function getHiddenProp(){
    var prefixes = ['webkit','moz','ms','o'];

    // if 'hidden' is natively supported just return it
    if ('hidden' in document) return 'hidden';

    // otherwise loop over all the known prefixes until we find one
    for (var i = 0; i < prefixes.length; i++){
      if ((prefixes[i] + 'Hidden') in document).
        return prefixes[i] + 'Hidden';
    }

    // otherwise it's not supported
    return null;
  }

  function isHidden() {
    var prop = getHiddenProp();
    if (!prop) return false;

    return document[prop];
  }

  // use the property name to generate the prefixed event name
  var visProp = getHiddenProp();
  if (visProp) {
    var evtname = visProp.replace(/[H|h]idden/,'') + 'visibilitychange';
    document.addEventListener(evtname, visChange);
  }

  var interval = null;
  function visChange() {
    if (isHidden())
      clearInterval(interval);
    else {
      updateTimeLoggerMenu();
      interval = setInterval(updateTimeLoggerMenu, 60000);
    }
  }

Working well for me. It would be great if you'll review it and implement it in your plugin.

Please notice that HTML5 must be supported to get it working, and if not, timer won't refresh (in my case i just don't care, but you can add "else setInterval(updateTimeLoggerMenu, 60000);" to "if (visProp)" just for compatibility).

[poxtihc]

I've tried to reproduce this an I can't but here's a couple of things you can do.

Did you remove the directory? ../plugins/time_logger
If the directory is still there remove it. Restart web server. Check to see if that fixed the issue.

It that doesn't fix it
Also run query against the database select * from schema_migrations where version like "%time_logger%" limit 0,25

If it exists delete it
delete from schema_migrations where version like "%time_logger%"

Restart Web server and check again.

No results removing ../plugins/time_logger and delete from schema_migrations where version like "%time_logger%"

ActionController::RoutingError (No route matches [GET] "/time_loggers/render_menu"):
actionpack (4.2.6) lib/action_dispatch/middleware/debug_exceptions.rb:21:in call' actionpack (4.2.6) lib/action_dispatch/middleware/show_exceptions.rb:30:in call'
railties (4.2.6) lib/rails/rack/logger.rb:38:in call_app' railties (4.2.6) lib/rails/rack/logger.rb:20:in block in call'
activesupport (4.2.6) lib/active_support/tagged_logging.rb:68:in block in tagged' activesupport (4.2.6) lib/active_support/tagged_logging.rb:26:in tagged'
activesupport (4.2.6) lib/active_support/tagged_logging.rb:68:in tagged' railties (4.2.6) lib/rails/rack/logger.rb:20:in call'
actionpack (4.2.6) lib/action_dispatch/middleware/request_id.rb:21:in call' rack (1.6.5) lib/rack/methodoverride.rb:22:in call'
rack (1.6.5) lib/rack/runtime.rb:18:in call' activesupport (4.2.6) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in call'
actionpack (4.2.6) lib/action_dispatch/middleware/static.rb:120:in call' rack (1.6.5) lib/rack/sendfile.rb:113:in call'
railties (4.2.6) lib/rails/engine.rb:518:in call' railties (4.2.6) lib/rails/application.rb:165:in call'
railties (4.2.6) lib/rails/railtie.rb:194:in public_send' railties (4.2.6) lib/rails/railtie.rb:194:in method_missing'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in process_request' /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:152:in accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113:in main_loop' /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in block (3 levels) in start_threads'
/usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'

[speedy32129]

ok I've figured this out!! I'm now using a real ide so tracing this was pretty easy. The first issue is when uninstalling the plugin the public_assets do not get removed.

Make sure to delete the plugin directory ../plugins/time_logger
You'll also have to remove ../public/plugin_assets/time_logger !!! This is a Rails bug and hasn't been fix for some time.

danaivehr I like your idea could you please share the file or clone my project so I can give you credit for helping fixing the issue.

[danaivehr]

@speedy32129 hello there after years! =)

Here is the app/views/time_loggers/_update_menu.html.erb file with that changes from #43 (comment)

<% if User.current.logged? and @project.present? and global_allowed_to?(User.current, :view_time_logger) %>
  <script type="text/javascript">
    $(function() {
      function updateStatus() {
        $.ajax({
          url:"<%=url_for :controller => '/time_loggers',:action => 'render_toolbar' %>",
          data:({<%= (@project.nil? ? nil : "project_id:#{@project.id},") %><%= (@issue.nil? ? nil : "issue_id:#{@issue.id}") %> }),
          cache:false,
          success: function(data){
            $('#time-logger-toolbar').replaceWith(data);
          },
          error: function(error) {
            var message = '<%= escape_javascript(l('time_logger_connection_lost')) %>'
            message += ' <a href="#" data-time-logger-refresh="true">Retry</a>'
            $('#time-logger-toolbar .timer-task').html(message)
          }
        });
      }

      function getHiddenProp(){
        var prefixes = ['webkit','moz','ms','o'];

        // if 'hidden' is natively supported just return it
        if ('hidden' in document) return 'hidden';

        // otherwise loop over all the known prefixes until we find one
        for (var i = 0; i < prefixes.length; i++){
          if ((prefixes[i] + 'Hidden') in document) 
            return prefixes[i] + 'Hidden';
        }

        // otherwise it's not supported
        return null;
      }

      function isHidden() {
        var prop = getHiddenProp();
        if (!prop) return false;

        return document[prop];
      }

      // use the property name to generate the prefixed event name
      var visProp = getHiddenProp();
      if (visProp) {
        var evtname = visProp.replace(/[H|h]idden/,'') + 'visibilitychange';
        document.addEventListener(evtname, visChange);
      }

      var interval = null;
      function visChange() {
        if (isHidden())
          clearInterval(interval);
        else {
          update();
          interval = setInterval(update, 60000);
        }
      }
      function update() {
        updateStatus();
        //updateIssues();
      }

      jQuery(document).ready(function($){
        $('#main').prepend('<%= escape_javascript(render :partial => 'time_loggers/toolbar') %>');
        //$(document).on('click', '[data-time-logger-refresh]', update)
        //setInterval(update, 60000);
        //updateIssues();
      });
    });
  </script>
<% end %>