Modify ↓

Opened 8 years ago

Closed 8 years ago

Last modified 8 years ago

#12977 closed defect (invalid)

multiple environment startup

Reported by: tomasz@… Owned by: osimons
Priority: normal Component: XmlRpcPlugin
Severity: normal Keywords:
Cc: tomasz@… Trac Release: 1.0

Description

I got a performance problem with xmlrpcPlugin. On my web page I send many calls (more than 7 - 7 and as many as many tickets match criterias)

After investigation I found, that each refreshing of page executes some enviroment startup, but not for each call - 4 times, 7, 9 and even 12 times - with the same number of tickets (just hitting refresh on web browser and counting lines of existance "enviroment starutp".

Today number of get tickets is 13, so calls are 20 each time, but number startups looks random.

Attachments (0)

Change History (15)

comment:1 Changed 8 years ago by Tomasz Brzezina

Cc: tomasz@… added

comment:2 in reply to:  description Changed 8 years ago by Ryan J Ollos

Replying to tomasz@…:

(just hitting refresh on web browser and counting lines of existance "enviroment starutp".

If each page load causes environment startup to be seen in the logs, you probably have an ​InstallationIssue. Which other plugins do you have installed?

comment:3 Changed 8 years ago by Tomasz Brzezina

only this:

  • TracAccountManager 0.4.4
  • TracXMLRPC 1.1.4

I read InstallationIssue hundreds times, and checked many options - no changes. I don't rule out that I missed something, but no idea what.

My apache2 conf looks now: 

    
    Alias /trac/TRAC1/chrome /var/www/html/trac1/trac/htdocs/
    WSGIDaemonProcess trac
    WSGIScriptAlias /trac /var/lib/trac/apache/trac.wsgi
    <Directory /var/lib/trac/apache>
      WSGIApplicationGroup %{GLOBAL}
      Require all granted
    </Directory>
    <Location ~ "/(trac|svn)/TRAC1/login">
      AuthUserFile /etc/apache2/users.trac1
      Require valid-user
    </Location>
    <Location ~ "/(trac|svn)/TRAC2">
      AuthUserFile /etc/apache2/users.trac2
      Require user user1 user2
    </Location>
    <Location ~ "/(trac|svn)/TRAC3">
      AuthUserFile /etc/apache2/users.trac2
      Require user user1 user3
    </Location>
    <Location /svn/>
      DAV svn
      SVNParentPath /var/lib/svn/
      AuthType Basic
      AuthName "My's SVN"
      AuthzSVNAccessFile /etc/subversion/access
    </Location>

I have few tracs on this site, but I focused on TRAC1 (Alias), which use xmlrpc very often.

I use debian stable repository (apt-get install trac), that's why it is rather old version of trac.

comment:4 Changed 8 years ago by Ryan J Ollos

Which version of Trac? Is the Environment Startup message seen frequently if you disable XmlRpcPlugin? Can you share a DEBUG level log file that demonstrates the issue?

comment:5 Changed 8 years ago by Tomasz Brzezina

I changed my rpc calls (Multicall) into 3 calls (couldn't less), but issue persist (of course it is between 1 and 3 ;D

In this case - all three calls executes environment startup

I'll check if this goes if i don't use xmlrpc 

2016-12-01 13:03:18,293 Trac[env] INFO: -------------------------------- environment startup [Trac 1.0.2] --------------------------------
2016-12-01 13:03:18,407 Trac[loader] DEBUG: Loading TracXMLRPC from /usr/local/lib/python2.7/dist-packages/TracXMLRPC-1.1.4-py2.7.egg
2016-12-01 13:03:18,544 Trac[loader] DEBUG: Loading acct_mgr.admin from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,619 Trac[loader] DEBUG: Loading acct_mgr.api from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,620 Trac[loader] DEBUG: Loading acct_mgr.db from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,620 Trac[loader] DEBUG: Loading acct_mgr.htfile from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,622 Trac[loader] DEBUG: Loading acct_mgr.http from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,623 Trac[loader] DEBUG: Loading acct_mgr.macros from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,624 Trac[loader] DEBUG: Loading acct_mgr.notification from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,626 Trac[loader] DEBUG: Loading acct_mgr.pwhash from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,626 Trac[loader] DEBUG: Loading acct_mgr.svnserve from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,628 Trac[loader] DEBUG: Loading acct_mgr.web_ui from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:18,628 Trac[loader] DEBUG: Loading trac.about from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,629 Trac[loader] DEBUG: Loading trac.admin.console from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,645 Trac[loader] DEBUG: Loading trac.admin.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,654 Trac[loader] DEBUG: Loading trac.attachment from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,655 Trac[loader] DEBUG: Loading trac.db.mysql from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,657 Trac[loader] DEBUG: Loading trac.db.postgres from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,658 Trac[loader] DEBUG: Loading trac.db.sqlite from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,675 Trac[loader] DEBUG: Loading trac.mimeview.patch from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,691 Trac[loader] DEBUG: Loading trac.mimeview.pygments from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,752 Trac[loader] DEBUG: Loading trac.mimeview.rst from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,984 Trac[loader] DEBUG: Loading trac.mimeview.txtl from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:18,994 Trac[loader] DEBUG: Skipping "trac.mimeview.txtl = trac.mimeview.txtl [textile]": ("DistributionNotFound: textile>=2.0" not found)
2016-12-01 13:03:18,995 Trac[loader] DEBUG: Loading trac.prefs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,002 Trac[loader] DEBUG: Loading trac.search from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,002 Trac[loader] DEBUG: Loading trac.ticket.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,011 Trac[loader] DEBUG: Loading trac.ticket.batch from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,013 Trac[loader] DEBUG: Loading trac.ticket.query from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,013 Trac[loader] DEBUG: Loading trac.ticket.report from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,025 Trac[loader] DEBUG: Loading trac.ticket.roadmap from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,033 Trac[loader] DEBUG: Loading trac.ticket.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,034 Trac[loader] DEBUG: Loading trac.timeline from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,040 Trac[loader] DEBUG: Loading trac.versioncontrol.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,050 Trac[loader] DEBUG: Loading trac.versioncontrol.svn_authz from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,052 Trac[loader] DEBUG: Loading trac.versioncontrol.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,069 Trac[loader] DEBUG: Loading trac.web.auth from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,070 Trac[loader] DEBUG: Loading trac.web.main from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,070 Trac[loader] DEBUG: Loading trac.web.session from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,070 Trac[loader] DEBUG: Loading trac.wiki.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,070 Trac[loader] DEBUG: Loading trac.wiki.interwiki from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,073 Trac[loader] DEBUG: Loading trac.wiki.macros from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,074 Trac[loader] DEBUG: Loading trac.wiki.web_api from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,075 Trac[loader] DEBUG: Loading trac.wiki.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,078 Trac[loader] DEBUG: Loading tracopt.mimeview.enscript from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,080 Trac[loader] DEBUG: Loading tracopt.mimeview.php from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,081 Trac[loader] DEBUG: Loading tracopt.mimeview.silvercity from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,098 Trac[loader] DEBUG: Skipping "tracopt.mimeview.silvercity = tracopt.mimeview.silvercity [silvercity]": ("DistributionNotFound: SilverCity>=0.9.4" not found)
2016-12-01 13:03:19,099 Trac[loader] DEBUG: Loading tracopt.perm.authz_policy from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,109 Trac[loader] DEBUG: Skipping "tracopt.perm.authz_policy = tracopt.perm.authz_policy [configobj]": ("DistributionNotFound: ConfigObj" not found)
2016-12-01 13:03:19,109 Trac[loader] DEBUG: Loading tracopt.perm.config_perm_provider from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,110 Trac[loader] DEBUG: Loading tracopt.ticket.clone from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,112 Trac[loader] DEBUG: Loading tracopt.ticket.commit_updater from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,114 Trac[loader] DEBUG: Loading tracopt.ticket.deleter from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,115 Trac[loader] DEBUG: Loading tracopt.versioncontrol.git.git_fs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,127 Trac[loader] DEBUG: Loading tracopt.versioncontrol.svn.svn_fs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,137 Trac[loader] DEBUG: Loading tracopt.versioncontrol.svn.svn_prop from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:19,142 Trac[default_workflow] DEBUG: Workflow actions at initialization: {u'resolve': {u'operations': [u'set_resolution'], 'name': u'resolve', 'default': 0, 'newstate': u'closed', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, u'accept': {u'operations': [u'set_owner_to_self'], 'name': u'accept', 'default': 0, 'newstate': u'accepted', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, u'leave': {u'operations': [u'leave_status'], 'name': u'leave', u'default': 1, 'newstate': u'*', 'oldstates': [u'*'], 'permissions': []}, u'reopen': {u'operations': [u'del_resolution'], 'name': u'reopen', 'default': 0, 'newstate': u'reopened', 'oldstates': [u'closed'], u'permissions': [u'TICKET_CREATE']}, u'reassign': {u'operations': [u'set_owner'], 'name': u'reassign', 'default': 0, 'newstate': u'assigned', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, '_reset': {'operations': ['reset_workflow'], 'name': 'reset', 'default': 0, 'newstate': 'new', 'oldstates': [], 'permissions': []}}

2016-12-01 13:03:19,161 Trac[env] WARNING: base_url option not set in configuration, generated links may be incorrect
2016-12-01 13:03:19,161 Trac[main] DEBUG: Dispatching <RequestWithSession "POST '/login/rpc'">
2016-12-01 13:03:19,266 Trac[web_ui] DEBUG: LoginModule._remote_user: Authentication attempted for 'None'
2016-12-01 13:03:19,267 Trac[session] DEBUG: Retrieving session for ID u'tomasz.brzezina'
2016-12-01 13:03:19,307 Trac[main] DEBUG: Negotiated locale: None -> en_US
2016-12-01 13:03:19,710 Trac[svn_fs] DEBUG: Subversion bindings imported
2016-12-01 13:03:19,764 Trac[api] INFO: Synchronized '(default)' repository in 0.50 seconds
2016-12-01 13:03:19,765 Trac[web_ui] DEBUG: RPC incoming request of content type 'application/json' dispatched to <tracrpc.json_rpc.JsonRpcProtocol object at 0x7efd526e2810>
2016-12-01 13:03:19,766 Trac[web_ui] DEBUG: RPC(JSON-RPC) call by 'tomasz.brzezina'
2016-12-01 13:03:19,768 Trac[json_rpc] INFO: RPC(json) JSON-RPC request ID : None.
2016-12-01 13:03:19,769 Trac[json_rpc] DEBUG: RPC(json) Multicall request {u'params': [{u'params': [], u'method': u'ticket.severity.getAll'}, {u'params': [], u'method': u'ticket.type.getAll'}, {u'params': [], u'method': u'ticket.priority.getAll'}, {u'params': [u'status!=closed&owner=tomasz.brzezina'], u'method': u'ticket.query'}, {u'params': [u'status!=closed&reporter=tomasz.brzezina&owner!=tomasz.brzezina'], u'method': u'ticket.query'}], u'method': u'system.multicall'}
2016-12-01 13:03:19,772 Trac[api] DEBUG: action controllers for ticket workflow: ['ConfigurableTicketWorkflow']
2016-12-01 13:03:19,775 Trac[web_ui] DEBUG: RPC(JSON-RPC) call by 'tomasz.brzezina' system.multicall
2016-12-01 13:03:19,814 Trac[query] DEBUG: Count results in Query: 7
2016-12-01 13:03:19,821 Trac[query] DEBUG: Count results in Query: 5
2016-12-01 13:03:19,824 Trac[json_rpc] DEBUG: RPC(json) result: {'id': None, 'resu(...)50, 53, 59], 'error': None}], 'error': None}
2016-12-01 13:03:19,826 Trac[json_rpc] DEBUG: RPC(json) encoded response: {"id": null, "result": [{"id": null, "result": (...) 50, 53, 59], "error": null}], "error": null}

2016-12-01 13:03:20,373 Trac[env] INFO: -------------------------------- environment startup [Trac 1.0.2] --------------------------------
2016-12-01 13:03:20,401 Trac[loader] DEBUG: Loading TracXMLRPC from /usr/local/lib/python2.7/dist-packages/TracXMLRPC-1.1.4-py2.7.egg
2016-12-01 13:03:20,440 Trac[loader] DEBUG: Loading acct_mgr.admin from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,456 Trac[loader] DEBUG: Loading acct_mgr.api from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,457 Trac[loader] DEBUG: Loading acct_mgr.db from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,459 Trac[loader] DEBUG: Loading acct_mgr.htfile from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,461 Trac[loader] DEBUG: Loading acct_mgr.http from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,463 Trac[loader] DEBUG: Loading acct_mgr.macros from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,465 Trac[loader] DEBUG: Loading acct_mgr.notification from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,468 Trac[loader] DEBUG: Loading acct_mgr.pwhash from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,469 Trac[loader] DEBUG: Loading acct_mgr.svnserve from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,472 Trac[loader] DEBUG: Loading acct_mgr.web_ui from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:20,473 Trac[loader] DEBUG: Loading trac.about from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,475 Trac[loader] DEBUG: Loading trac.admin.console from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,478 Trac[loader] DEBUG: Loading trac.admin.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,481 Trac[loader] DEBUG: Loading trac.attachment from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,482 Trac[loader] DEBUG: Loading trac.db.mysql from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,485 Trac[loader] DEBUG: Loading trac.db.postgres from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,486 Trac[loader] DEBUG: Loading trac.db.sqlite from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,492 Trac[loader] DEBUG: Loading trac.mimeview.patch from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,494 Trac[loader] DEBUG: Loading trac.mimeview.pygments from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,509 Trac[loader] DEBUG: Loading trac.mimeview.rst from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,650 Trac[loader] DEBUG: Loading trac.mimeview.txtl from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,661 Trac[loader] DEBUG: Skipping "trac.mimeview.txtl = trac.mimeview.txtl [textile]": ("DistributionNotFound: textile>=2.0" not found)
2016-12-01 13:03:20,662 Trac[loader] DEBUG: Loading trac.prefs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,664 Trac[loader] DEBUG: Loading trac.search from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,665 Trac[loader] DEBUG: Loading trac.ticket.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,668 Trac[loader] DEBUG: Loading trac.ticket.batch from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,670 Trac[loader] DEBUG: Loading trac.ticket.query from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,671 Trac[loader] DEBUG: Loading trac.ticket.report from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,676 Trac[loader] DEBUG: Loading trac.ticket.roadmap from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,679 Trac[loader] DEBUG: Loading trac.ticket.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,680 Trac[loader] DEBUG: Loading trac.timeline from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,683 Trac[loader] DEBUG: Loading trac.versioncontrol.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,685 Trac[loader] DEBUG: Loading trac.versioncontrol.svn_authz from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,687 Trac[loader] DEBUG: Loading trac.versioncontrol.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,699 Trac[loader] DEBUG: Loading trac.web.auth from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,703 Trac[loader] DEBUG: Loading trac.web.main from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,704 Trac[loader] DEBUG: Loading trac.web.session from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,704 Trac[loader] DEBUG: Loading trac.wiki.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,704 Trac[loader] DEBUG: Loading trac.wiki.interwiki from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,706 Trac[loader] DEBUG: Loading trac.wiki.macros from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,707 Trac[loader] DEBUG: Loading trac.wiki.web_api from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,707 Trac[loader] DEBUG: Loading trac.wiki.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,709 Trac[loader] DEBUG: Loading tracopt.mimeview.enscript from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,710 Trac[loader] DEBUG: Loading tracopt.mimeview.php from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,711 Trac[loader] DEBUG: Loading tracopt.mimeview.silvercity from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,724 Trac[loader] DEBUG: Skipping "tracopt.mimeview.silvercity = tracopt.mimeview.silvercity [silvercity]": ("DistributionNotFound: SilverCity>=0.9.4" not found)
2016-12-01 13:03:20,725 Trac[loader] DEBUG: Loading tracopt.perm.authz_policy from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,735 Trac[loader] DEBUG: Skipping "tracopt.perm.authz_policy = tracopt.perm.authz_policy [configobj]": ("DistributionNotFound: ConfigObj" not found)
2016-12-01 13:03:20,735 Trac[loader] DEBUG: Loading tracopt.perm.config_perm_provider from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,736 Trac[loader] DEBUG: Loading tracopt.ticket.clone from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,737 Trac[loader] DEBUG: Loading tracopt.ticket.commit_updater from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,739 Trac[loader] DEBUG: Loading tracopt.ticket.deleter from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,740 Trac[loader] DEBUG: Loading tracopt.versioncontrol.git.git_fs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,746 Trac[loader] DEBUG: Loading tracopt.versioncontrol.svn.svn_fs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,755 Trac[loader] DEBUG: Loading tracopt.versioncontrol.svn.svn_prop from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:20,761 Trac[default_workflow] DEBUG: Workflow actions at initialization: {u'resolve': {u'operations': [u'set_resolution'], 'name': u'resolve', 'default': 0, 'newstate': u'closed', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, u'accept': {u'operations': [u'set_owner_to_self'], 'name': u'accept', 'default': 0, 'newstate': u'accepted', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, u'leave': {u'operations': [u'leave_status'], 'name': u'leave', u'default': 1, 'newstate': u'*', 'oldstates': [u'*'], 'permissions': []}, u'reopen': {u'operations': [u'del_resolution'], 'name': u'reopen', 'default': 0, 'newstate': u'reopened', 'oldstates': [u'closed'], u'permissions': [u'TICKET_CREATE']}, u'reassign': {u'operations': [u'set_owner'], 'name': u'reassign', 'default': 0, 'newstate': u'assigned', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, '_reset': {'operations': ['reset_workflow'], 'name': 'reset', 'default': 0, 'newstate': 'new', 'oldstates': [], 'permissions': []}}

2016-12-01 13:03:20,767 Trac[env] WARNING: base_url option not set in configuration, generated links may be incorrect
2016-12-01 13:03:20,767 Trac[main] DEBUG: Dispatching <RequestWithSession "POST '/login/rpc'">
2016-12-01 13:03:20,787 Trac[web_ui] DEBUG: LoginModule._remote_user: Authentication attempted for 'None'
2016-12-01 13:03:20,787 Trac[session] DEBUG: Retrieving session for ID u'tomasz.brzezina'
2016-12-01 13:03:20,793 Trac[main] DEBUG: Negotiated locale: None -> en_US
2016-12-01 13:03:20,890 Trac[svn_fs] DEBUG: Subversion bindings imported
2016-12-01 13:03:20,896 Trac[api] INFO: Synchronized '(default)' repository in 0.11 seconds
2016-12-01 13:03:20,896 Trac[web_ui] DEBUG: RPC incoming request of content type 'application/json' dispatched to <tracrpc.json_rpc.JsonRpcProtocol object at 0x7efd52554810>
2016-12-01 13:03:20,897 Trac[web_ui] DEBUG: RPC(JSON-RPC) call by 'tomasz.brzezina'
2016-12-01 13:03:20,897 Trac[json_rpc] INFO: RPC(json) JSON-RPC request ID : None.
2016-12-01 13:03:20,898 Trac[api] DEBUG: action controllers for ticket workflow: ['ConfigurableTicketWorkflow']
2016-12-01 13:03:20,900 Trac[web_ui] DEBUG: RPC(JSON-RPC) call by 'tomasz.brzezina' ticket.getActions
2016-12-01 13:03:20,908 Trac[default_workflow] DEBUG: render_ticket_action_control: action "leave"
2016-12-01 13:03:20,909 Trac[default_workflow] DEBUG: render_ticket_action_control: action "resolve"
2016-12-01 13:03:20,911 Trac[default_workflow] DEBUG: render_ticket_action_control: action "reassign"
2016-12-01 13:03:20,924 Trac[default_workflow] DEBUG: render_ticket_action_control: action "accept"
2016-12-01 13:03:20,925 Trac[json_rpc] DEBUG: RPC(json) result: {'id': None, 'result': [(u'le(...)t status will be 'accepted'.", []]], "error": null}

2016-12-01 13:03:21,534 Trac[env] INFO: -------------------------------- environment startup [Trac 1.0.2] --------------------------------
2016-12-01 13:03:21,563 Trac[loader] DEBUG: Loading TracXMLRPC from /usr/local/lib/python2.7/dist-packages/TracXMLRPC-1.1.4-py2.7.egg
2016-12-01 13:03:21,604 Trac[loader] DEBUG: Loading acct_mgr.admin from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,648 Trac[loader] DEBUG: Loading acct_mgr.api from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,650 Trac[loader] DEBUG: Loading acct_mgr.db from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,651 Trac[loader] DEBUG: Loading acct_mgr.htfile from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,654 Trac[loader] DEBUG: Loading acct_mgr.http from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,656 Trac[loader] DEBUG: Loading acct_mgr.macros from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,659 Trac[loader] DEBUG: Loading acct_mgr.notification from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,661 Trac[loader] DEBUG: Loading acct_mgr.pwhash from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,663 Trac[loader] DEBUG: Loading acct_mgr.svnserve from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,666 Trac[loader] DEBUG: Loading acct_mgr.web_ui from /usr/local/lib/python2.7/dist-packages/TracAccountManager-0.4.4-py2.7.egg
2016-12-01 13:03:21,667 Trac[loader] DEBUG: Loading trac.about from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,670 Trac[loader] DEBUG: Loading trac.admin.console from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,682 Trac[loader] DEBUG: Loading trac.admin.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,685 Trac[loader] DEBUG: Loading trac.attachment from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,686 Trac[loader] DEBUG: Loading trac.db.mysql from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,689 Trac[loader] DEBUG: Loading trac.db.postgres from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,692 Trac[loader] DEBUG: Loading trac.db.sqlite from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,708 Trac[loader] DEBUG: Loading trac.mimeview.patch from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,710 Trac[loader] DEBUG: Loading trac.mimeview.pygments from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,741 Trac[loader] DEBUG: Loading trac.mimeview.rst from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,945 Trac[loader] DEBUG: Loading trac.mimeview.txtl from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,956 Trac[loader] DEBUG: Skipping "trac.mimeview.txtl = trac.mimeview.txtl [textile]": ("DistributionNotFound: textile>=2.0" not found)
2016-12-01 13:03:21,958 Trac[loader] DEBUG: Loading trac.prefs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,959 Trac[loader] DEBUG: Loading trac.search from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,961 Trac[loader] DEBUG: Loading trac.ticket.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,963 Trac[loader] DEBUG: Loading trac.ticket.batch from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,965 Trac[loader] DEBUG: Loading trac.ticket.query from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,967 Trac[loader] DEBUG: Loading trac.ticket.report from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,971 Trac[loader] DEBUG: Loading trac.ticket.roadmap from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,974 Trac[loader] DEBUG: Loading trac.ticket.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,976 Trac[loader] DEBUG: Loading trac.timeline from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,979 Trac[loader] DEBUG: Loading trac.versioncontrol.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,981 Trac[loader] DEBUG: Loading trac.versioncontrol.svn_authz from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,983 Trac[loader] DEBUG: Loading trac.versioncontrol.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,995 Trac[loader] DEBUG: Loading trac.web.auth from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,996 Trac[loader] DEBUG: Loading trac.web.main from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,997 Trac[loader] DEBUG: Loading trac.web.session from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,998 Trac[loader] DEBUG: Loading trac.wiki.admin from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:21,999 Trac[loader] DEBUG: Loading trac.wiki.interwiki from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,002 Trac[loader] DEBUG: Loading trac.wiki.macros from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,003 Trac[loader] DEBUG: Loading trac.wiki.web_api from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,005 Trac[loader] DEBUG: Loading trac.wiki.web_ui from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,007 Trac[loader] DEBUG: Loading tracopt.mimeview.enscript from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,010 Trac[loader] DEBUG: Loading tracopt.mimeview.php from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,011 Trac[loader] DEBUG: Loading tracopt.mimeview.silvercity from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,026 Trac[loader] DEBUG: Skipping "tracopt.mimeview.silvercity = tracopt.mimeview.silvercity [silvercity]": ("DistributionNotFound: SilverCity>=0.9.4" not found)
2016-12-01 13:03:22,027 Trac[loader] DEBUG: Loading tracopt.perm.authz_policy from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,038 Trac[loader] DEBUG: Skipping "tracopt.perm.authz_policy = tracopt.perm.authz_policy [configobj]": ("DistributionNotFound: ConfigObj" not found)
2016-12-01 13:03:22,039 Trac[loader] DEBUG: Loading tracopt.perm.config_perm_provider from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,041 Trac[loader] DEBUG: Loading tracopt.ticket.clone from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,042 Trac[loader] DEBUG: Loading tracopt.ticket.commit_updater from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,046 Trac[loader] DEBUG: Loading tracopt.ticket.deleter from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,047 Trac[loader] DEBUG: Loading tracopt.versioncontrol.git.git_fs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,054 Trac[loader] DEBUG: Loading tracopt.versioncontrol.svn.svn_fs from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,064 Trac[loader] DEBUG: Loading tracopt.versioncontrol.svn.svn_prop from /usr/lib/python2.7/dist-packages
2016-12-01 13:03:22,070 Trac[default_workflow] DEBUG: Workflow actions at initialization: {u'resolve': {u'operations': [u'set_resolution'], 'name': u'resolve', 'default': 0, 'newstate': u'closed', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, u'accept': {u'operations': [u'set_owner_to_self'], 'name': u'accept', 'default': 0, 'newstate': u'accepted', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, u'leave': {u'operations': [u'leave_status'], 'name': u'leave', u'default': 1, 'newstate': u'*', 'oldstates': [u'*'], 'permissions': []}, u'reopen': {u'operations': [u'del_resolution'], 'name': u'reopen', 'default': 0, 'newstate': u'reopened', 'oldstates': [u'closed'], u'permissions': [u'TICKET_CREATE']}, u'reassign': {u'operations': [u'set_owner'], 'name': u'reassign', 'default': 0, 'newstate': u'assigned', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], u'permissions': [u'TICKET_MODIFY']}, '_reset': {'operations': ['reset_workflow'], 'name': 'reset', 'default': 0, 'newstate': 'new', 'oldstates': [], 'permissions': []}}

2016-12-01 13:03:22,076 Trac[env] WARNING: base_url option not set in configuration, generated links may be incorrect
2016-12-01 13:03:22,077 Trac[main] DEBUG: Dispatching <RequestWithSession "POST '/login/rpc'">
2016-12-01 13:03:22,097 Trac[web_ui] DEBUG: LoginModule._remote_user: Authentication attempted for 'None'
2016-12-01 13:03:22,098 Trac[session] DEBUG: Retrieving session for ID u'tomasz.brzezina'
2016-12-01 13:03:22,103 Trac[main] DEBUG: Negotiated locale: None -> en_US
2016-12-01 13:03:22,281 Trac[svn_fs] DEBUG: Subversion bindings imported
2016-12-01 13:03:22,304 Trac[api] INFO: Synchronized '(default)' repository in 0.21 seconds
2016-12-01 13:03:22,304 Trac[web_ui] DEBUG: RPC incoming request of content type 'application/json' dispatched to <tracrpc.json_rpc.JsonRpcProtocol object at 0x7efd52556810>
2016-12-01 13:03:22,305 Trac[web_ui] DEBUG: RPC(JSON-RPC) call by 'tomasz.brzezina'
2016-12-01 13:03:22,306 Trac[json_rpc] INFO: RPC(json) JSON-RPC request ID : None.
2016-12-01 13:03:22,307 Trac[json_rpc] DEBUG: RPC(json) Multicall request {u'params': [{u'params': [20], u'method': u'ticket.get'}, {u'params': [36], u'method': u'ticket.get'}, {u'params': [46], u'method': u'ticket.get'}, {u'params': [47], u'method': u'ticket.get'}, {u'params': [51], u'method': u'ticket.get'}, {u'params': [52], u'method': u'ticket.get'}, {u'params': [73], u'method': u'ticket.get'}, {u'params': [21], u'method': u'ticket.get'}, {u'params': [49], u'method': u'ticket.get'}, {u'params': [50], u'method': u'ticket.get'}, {u'params': [53], u'method': u'ticket.get'}, {u'params': [59], u'method': u'ticket.get'}], u'method': u'system.multicall'}
2016-12-01 13:03:22,308 Trac[api] DEBUG: action controllers for ticket workflow: ['ConfigurableTicketWorkflow']
2016-12-01 13:03:22,311 Trac[web_ui] DEBUG: RPC(JSON-RPC) call by 'tomasz.brzezina' system.multicall
2016-12-01 13:03:22,349 Trac[json_rpc] DEBUG: RPC(json) result: {'id': None, 'result': [{'id': None, 'result': [20, datetime.datetime(2015, 8, 29, 12, 3, 12, 80721,(...)ela'}], 'error': None}], 'error': None}
2016-12-01 13:03:22,351 Trac[json_rpc] DEBUG: RPC(json) encoded response: {"id": null, "result": [{"id": null, "result": [20, {"__jsonclass__": ["datetime", "2015-08-29T12:03:12"]}, (...)"severity": "dxxxla"}], "error": null}], "error": null}
Last edited 8 years ago by Ryan J Ollos (previous) (diff)

comment:6 Changed 8 years ago by Tomasz Brzezina

I go through trac up and down and only the first time after some time executes environment startup. After 40 second of pause enviroment startup appears, but after next 60 seconds - not. After next 20 seconds - again startup... I try one link again and again and after 7 tries environment startup appears.. I see no rules. Now 40 tries doesn't execute startup. 30 seconds of pause - and again.

comment:7 in reply to:  5 Changed 8 years ago by Ryan J Ollos

Replying to SledgehammerPL:

I'll check if this goes if i don't use xmlrpc

Also if you could testing with AccountManager disabled, that should provide good insight.

Make sure your egg cache is setup correctly (TracModWSGI). What version of setuptools do you have?

Last edited 8 years ago by Ryan J Ollos (previous) (diff)

comment:8 Changed 8 years ago by tomasz@…

disabling AccountManager changes nothing. Still about three environment startups.

python-setuptools 5.5.1-1

my trac.wsgi: 

import sys
sys.stdout = sys.stderr

import os
os.environ['TRAC_ENV_PARENT_DIR'] = '/var/lib/trac'
os.environ['PYTHON_EGG_CACHE'] = '/var/lib/trac/eggs'

import trac.web.main

application = trac.web.main.dispatch_request
Last edited 8 years ago by Ryan J Ollos (previous) (diff)

comment:9 in reply to:  8 Changed 8 years ago by Ryan J Ollos

Replying to tomasz@…:

python-setuptools 5.5.1-1

You may be encountering the setuptools 5.4 - 5.6 issue described in TracInstall#DeployingTrac. See the section setuptools warning. The documentation for wouldn't exist in your 1.0.2 version of Trac.

comment:10 Changed 8 years ago by tomasz@…

No changes...

comment:11 Changed 8 years ago by Ryan J Ollos

Did you try disabling XmlRpcPlugin?

comment:12 Changed 8 years ago by tomasz@…

If I disable XMLRpcPlugin how could I make a test?

comment:13 Changed 8 years ago by Ryan J Ollos

Let's back up to comment:2. I had the understanding that you would see Environment Startup messages in the logs by just reloading the web page. Under normal operation you should only see Environment Startup when restarting/reloading the web server or making a configuration change in trac.ini. So if you see Environment startup due to normal interaction with the Trac site pages, then we have a configuration problem that is outside the scope of XmlRpcPlugin.

I would like to determine first if the Environment Startup messages appear due to normal interaction with the Trac site (which is an issue I've seen before), or if they only occur due to interaction through XmlRpc.

Also, are there any other exception or error messages in your log files?

comment:14 Changed 8 years ago by Tomasz Brzezina

I've uninstall plugin now, and problem persists. So it isn't connected with xmlrpc plugin at all. I think, that I have to make ticket in trac now...

comment:15 in reply to:  14 Changed 8 years ago by Ryan J Ollos

Resolution: → invalid
Status: new → closed

Replying to SledgehammerPL:

I've uninstall plugin now, and problem persists. So it isn't connected with xmlrpc plugin at all. I think, that I have to make ticket in trac now...

Please ask on the ​trac:MailingList. You'll reach a better audience there, and this is certainly an ​InstallationIssue, not a defect with Trac. Let's continue the discussion in the mailing list thread you create. I have some more ideas on what to investigate.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain osimons.
The resolution will be deleted. Next status will be 'reopened'.

Add Comment

E-mail address and name can be saved in the Preferences.

Attachments ↑ Description ↑
 
Note: See TracTickets for help on using tickets.