trac-admin repository sync/resync randomly stops syncing

[adf@…]

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.

[Jun Omae]

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

[anonymous]

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.

[Jun Omae]

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.

[Jun Omae]

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

[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.

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.

[Jun Omae]

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.

• [42214058c/jomae.git] (for Trac 1.2.x)
• [7b4a794de/jomae.git] (for Trac 1.0.x)

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)

[anonymous]

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',)

[Jun Omae]

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

[Ryan J Ollos]

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).

[Ryan J Ollos]

Replying to Jun Omae:

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

• [42214058c/jomae.git] (for Trac 1.2.x)
• [7b4a794de/jomae.git] (for Trac 1.0.x)

The changes look good to me.

[Jun Omae]

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

[Ryan J Ollos]

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​)

[Jun Omae]

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

[Ryan J Ollos]

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