Edgewall Software
Modify

Opened 6 years ago

Closed 6 years ago

#12993 closed defect (fixed)

trac-admin repository sync/resync randomly stops syncing

Reported by: adf@… Owned by: Jun Omae
Priority: normal Milestone: 1.0.17
Component: version control Version: 1.2.2
Severity: normal Keywords:
Cc: Branch:
Release Notes:

Log messages for cached repository include the repository name.

API Changes:
Internal Changes:

Description (last modified by anonymous)

There are 36868 revisions in my repo.

I am trying to sync the repo after adding it, it stopped doing it after a few hundred, then after a few thousand, then it did around 22,000 and stopped, then on running again, just stoped at same point, then run again, carried on.

[root@svnmirror ~]# trac-admin /var/trac repository sync INFORMATE
Resyncing repository history for INFORMATE... 
23281 revisions cached.
Done.
[root@svnmirror ~]# trac-admin /var/trac repository sync INFORMATE
Resyncing repository history for INFORMATE... 
23281 revisions cached.
Done.

Then started again, processing revision 24240 …

[root@svnmirror ~]# trac-admin /var/trac repository sync INFORMATE
Resyncing repository history for INFORMATE... 
 [24240]

and stopped.

[root@svnmirror ~]# trac-admin /var/trac repository sync INFORMATE
Resyncing repository history for INFORMATE... 
2539 revisions cached.
Done.

Started again, but this time, its processing revision 1536??

[root@svnmirror ~]# trac-admin /var/trac repository sync INFORMATE
Resyncing repository history for INFORMATE... 
 [1536]

If I look in trac, it shows the last revision as 36868 but shows no information for those revisions.

No errors are reported, so not sure what's going on.

The server is running in a VM. CentOS 6.5 and using sqlite as the database.

There are multiple repositories configured but not all have been synchronised yet. The DB is around 120MB currently.

Attachments (0)

Change History (16)

comment:1 by Jun Omae, 6 years ago

Component: generalversion control
Description: modified (diff)

comment:2 by Jun Omae, 6 years ago

Please post System Information in your Trac and trac.log with DEBUG level when executing trac-admin resync ....

comment:3 by anonymous, 6 years ago

Component: version controlgeneral
Description: modified (diff)

It's a 'database is locked' issue.

trac-admin /var/trac repository sync INFORMATE

2018-03-12 14:13:28,519 Trac[cache] INFO: Trying to sync revision [26939]
...

trac-admin /var/trac repository sync DEMA

2018-03-12 14:13:31,882 Trac[cache] INFO: repos rev [2584] != cached rev [None]
...

the DEMA sync starts processing some big revisions …

2018-03-12 14:13:34,203 Trac[cache] DEBUG: Caching node change in [5]: (u'tags/SP13/zMTSUsr.cls', 'file', 'add', None, -1)
2018-03-12 14:13:34,283 Trac[cache] INFO: Trying to sync revision [6]
2018-03-12 14:13:34,287 Trac[cache] DEBUG: Caching node change in [6]: (u'tags/SP14', 'dir', 'move', u'tags/SP13', 5)
2018-03-12 14:13:34,296 Trac[cache] INFO: Trying to sync revision [7]
2018-03-12 14:13:34,300 Trac[cache] DEBUG: Caching node change in [7]: (u'tags/SP14Plus', 'dir', 'add', None, -1)
2018-03-12 14:13:34,311 Trac[cache] INFO: Trying to sync revision [8]
2018-03-12 14:13:38,643 Trac[cache] WARNING: Revision 26939 already cached: OperationalError('database is locked',)
2018-03-12 14:13:39,292 Trac[cache] INFO: Resetting "repository_dir": svn:6bbf3ac7-fb38-469b-93a1-a286480b79be:/var/svn/products/INFORMATE
2018-03-12 14:13:39,310 Trac[cache] DEBUG: cache metadata undefined (youngest_rev=0)
2018-03-12 14:13:39,310 Trac[cache] INFO: repos rev [36830] != cached rev [None]
2018-03-12 14:13:39,312 Trac[cache] INFO: Trying to sync revision [1]
2018-03-12 14:13:40,258 Trac[cache] DEBUG: Caching node change in [8]: (u'tags/SP14Plus/1', 'file', 'add', None, -1)

I can work around it by stopping the background tasks while I do the initial resyncs.

Last edited 6 years ago by Jun Omae (previous) (diff)

comment:4 by Jun Omae, 6 years ago

Component: generalversion control

comment:5 by Jun Omae, 6 years ago

Weird. I tested with Trac 1.2.2/1.0.15 with SQLite and Subversion 1.8.8 but the issue cannot be reproduced. The repository sync command is restartable.

2018-03-13 12:25:47,840 Trac[cache] INFO: Trying to sync revision [264]
2018-03-13 12:25:47,841 Trac[cache] DEBUG: Caching node change in [264]: (u'trunk/ChangeLog', 'file', 'edit', u'trunk/ChangeLog', 263L)
2018-03-13 12:25:47,842 Trac[cache] INFO: Trying to sync revision [265]
2018-03-13 12:25:57,865 Trac[cache] WARNING: Revision 265 already cached: OperationalError('database is locked',)
2018-03-13 12:27:44,021 Trac[env] INFO: -------------------------------- environment startup [Trac 1.2.2] --------------------------------
...
2018-03-13 12:27:44,438 Trac[svn_fs] DEBUG: Subversion bindings imported
2018-03-13 12:27:44,441 Trac[cache] INFO: repos rev [16103] != cached rev [264]
2018-03-13 12:27:44,442 Trac[cache] INFO: Trying to sync revision [265]
2018-03-13 12:27:44,443 Trac[cache] DEBUG: Caching node change in [265]: (u'trunk/ChangeLog', 'file', 'edit', u'trunk/ChangeLog', 264L)

Please share System Information and Installed Plugins of About Trac page.

Also, I guess your Trac has a lot of concurrent requests. We recommend to use PostgreSQL or MySQL.

Last edited 6 years ago by Jun Omae (previous) (diff)

comment:6 by Jun Omae, 6 years ago

Workaround is set 0 (or large number) to [trac] timeout option (see TracIni#trac-timeout-option).

comment:7 by anonymous, 6 years ago

Please share System Information and Installed Plugins of About Trac page.

When I go to /trac/about I don't see System Information or Installed Plugins, just some text explaining what trac is.

I tested with Trac 1.2.2/1.0.15 with SQLite and Subversion 1.8.8 but the issue cannot be reproduced.

I manually tested concurrency, and could not reproduce either. In the instance I found in the log it was doing the following:-

A manual sync was running for repo INFORMATE which has 33000+ revisions and needed to cache many 1000s of revisions, so was taking a while.

During this, a background sync of another repository (DEMA I think) started that needed to sync from rev 1, the early checkins were large, many 100s of files, so rev 5 had a lot of files, as did rev 8, and I wondered if rev 5 being dealt with held a lock long enough for the sqlite lock to timeout that the INFORMATE sync was waiting for.

This was a rather non-typical scenario as I was just setting up trac, and needing to sync many 10,000 revisions manually, whilst at the same time allowing background syncs to run. a) the background syncs don't need to run yet, as I am just setting things up, and b) normally they would be small (few revisions) syncs as and when the repo is updated. Its a subversion mirror/backup, so pulls revisions from live every 15 minutes, so there may be more than one revision pulled, hence not using trac-admin changeset added.

comment:8 by Jun Omae, 6 years ago

Milestone: 1.0.17
Owner: set to Jun Omae
Status: newassigned

Okay. I guess 3 processes concurrently executed repository sync or repository resync. If there is Cleaning cache in trac.log, you've executed repository resync. It is not a defect since resetting cache by resync.

Process 1 - repository sync DEMA

2018-03-12 14:13:34,203 Trac[cache] DEBUG: Caching node change in [5]: (u'tags/SP13/zMTSUsr.cls', 'file', 'add', None, -1)
2018-03-12 14:13:34,283 Trac[cache] INFO: Trying to sync revision [6]
2018-03-12 14:13:34,287 Trac[cache] DEBUG: Caching node change in [6]: (u'tags/SP14', 'dir', 'move', u'tags/SP13', 5)
2018-03-12 14:13:34,296 Trac[cache] INFO: Trying to sync revision [7]
2018-03-12 14:13:34,300 Trac[cache] DEBUG: Caching node change in [7]: (u'tags/SP14Plus', 'dir', 'add', None, -1)
2018-03-12 14:13:34,311 Trac[cache] INFO: Trying to sync revision [8]
2018-03-12 14:13:40,258 Trac[cache] DEBUG: Caching node change in [8]: (u'tags/SP14Plus/1', 'file', 'add', None, -1)

Process 2 - repository sync INFORMATE

2018-03-12 14:13:38,643 Trac[cache] WARNING: Revision 26939 already cached: OperationalError('database is locked',)

Process 3 - repository resync INFORMATE (not sync)

2018-03-12 14:13:39,292 Trac[cache] INFO: Resetting "repository_dir": svn:6bbf3ac7-fb38-469b-93a1-a286480b79be:/var/svn/products/INFORMATE
2018-03-12 14:13:39,310 Trac[cache] DEBUG: cache metadata undefined (youngest_rev=0)
2018-03-12 14:13:39,310 Trac[cache] INFO: repos rev [36830] != cached rev [None]
2018-03-12 14:13:39,312 Trac[cache] INFO: Trying to sync revision [1]

However, I think we could improve the logging to make helpful for troubleshooting.

After the changes:

2018-03-13 23:32:26,594 Trac[cache] INFO: Cleaning cache in '(default)'
2018-03-13 23:32:26,595 Trac[cache] INFO: Resetting "repository_dir": svn:92ea810a-adf3-0310-b540-bef912dcf5ba:/var/svn/svnrepos
2018-03-13 23:32:26,596 Trac[cache] DEBUG: cache metadata undefined (youngest_rev=0, reponame=(default))
2018-03-13 23:32:26,596 Trac[cache] INFO: repos rev [31] != cached rev [None] in '(default)'
2018-03-13 23:32:26,596 Trac[cache] INFO: Trying to sync revision [1] in '(default)'
2018-03-13 23:32:26,597 Trac[cache] DEBUG: Caching node change in [1] in '(default)': (u'branches', 'dir', 'add', None, -1)

comment:9 by anonymous, 6 years ago

Not sure if you are looking at different issue.

It doesn't really matter if I was sync or resync the INFORMATE, the point is, it was running its sync in foreground, all 33000+ revisions or whatever revisions remained after the last attempt, and it then crashed out seemingly without any error (nothing reported on screen), because a background sync (on DEMA) started syncing revisions, some of which were very large revisions (initial checkins), which then caused the INFORMATE sync/resync to crash out with

    2018-03-12 14:13:38,643 Trac[cache] WARNING: Revision 26939 already cached: OperationalError('database is locked',)
Last edited 6 years ago by Jun Omae (previous) (diff)

comment:10 by Jun Omae, 6 years ago

I think you should use PostgreSQL/MySQL rather than SQLite for large Trac site. Otherwise, try to set 0 to [trac] timeout option.

Last edited 6 years ago by Jun Omae (previous) (diff)

in reply to:  7 comment:11 by Ryan J Ollos, 6 years ago

Replying to anonymous:

Please share System Information and Installed Plugins of About Trac page.

When I go to /trac/about I don't see System Information or Installed Plugins, just some text explaining what trac is.

You need to view About Trac with CONFIG_VIEW permissions (or TRAC_ADMIN, which grants CONFIG_VIEW).

in reply to:  8 comment:12 by Ryan J Ollos, 6 years ago

Replying to Jun Omae:

However, I think we could improve the logging to make helpful for troubleshooting.

The changes look good to me.

comment:13 by Jun Omae, 6 years ago

Thanks for the reviewing. Committed in [16601-16603].

comment:14 by Ryan J Ollos, 6 years ago

I haven't tested yet, but was it intentional to omit repository name from insert_changeset log message in r16603? (compare to 1.2-stable)

comment:15 by Jun Omae, 6 years ago

Oh, thanks. The omitted changes are wrong. Fixed in [16604].

comment:16 by Ryan J Ollos, 6 years ago

Release Notes: modified (diff)
Resolution: fixed
Status: assignedclosed

Closing since changes have been committed and there is no follow-up from reporter.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Jun Omae.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Jun Omae to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.