Context Navigation

← Previous Ticket
Next Ticket →

Ticket #1971 (closed defect: fixed)

Opened 2 years ago

Last modified 2 years ago

Nightly timered build using incorrect change for revision

Reported by:	zacw	Owned by:
Priority:	major	Milestone:	0.8.4
Version:	master	Keywords:
Cc:

Description

Summary

Given a list of changes, a nightly build performs the build using the revision from a historical change, not the latest change in the list.

Environment

Buildbot: 0.8.4-pre-639-g82d83fd
Twisted: 8.2.0
Jinja: 2.5.5
Python: 2.6.1 (r261:67515, Jun 24 2010, 21:47:49) [GCC 4.2.1 (Apple Inc. build 5646)]
Buildmaster platform: darwin

Steps to reproduce

(Ignore any obvious incongruities; copying/pasting the setup code from more generic code.)

Create a nightly build with the following generic setup:

c['schedulers'].append(timed.Nightly(
name ="icephone-unstable-nightly",
branch = "branches/icephone-1.10",
builderNames = ["icephone-unstable-nightly"],
hour = 7,
minute = 0,
onlyIfChanged = True))

Create an SVNPoller source for the change:

c['change_source'].append(SVNPoller(
svnurl = REPOSITORY_ICEPHONE,
project = "icephone",
svnuser = SVN_USERNAME,
svnpasswd = SVN_PASSWORD,
split_file = split_file_branches,
pollInterval = POLL_INTERVAL_SEC))

Perform a number of commits on the branch for the nightly.
Observe nightly build using the incorrect revision from a given change list.

Expected result

Nightly build sorts the list of its changes, and uses the latest change to pluck the revision for the build.

Actual Result

Nightly build picks an incorrect change, which yields the incorrect revision being built by the builder.

Debug Logs

From the master, at poll time:

2011-05-25 11:50:50-0400 [-] svnPoller: _process_changes 5435 .. 5438
2011-05-25 11:50:50-0400 [-] Adding change revision 5436
2011-05-25 11:50:50-0400 [-] Adding change revision 5437
2011-05-25 11:50:50-0400 [-] Adding change revision 5438
2011-05-25 11:50:50-0400 [-] WARNING: change source is using deprecated addChange parameter 'who'
2011-05-25 11:50:50-0400 [-] added change Change(who=u'zwest', files=[…redacted…], comments=u'…redacted…', revision=u'5436', when=1306338650, category=None, project=u'icephone', repository=u'…redacted/icephone') to database
2011-05-25 11:50:50-0400 [-] WARNING: change source is using deprecated addChange parameter 'who'
2011-05-25 11:50:50-0400 [-] added change Change(who=u'zwest', files=[…redacted…], comments=u'…redacted…', revision=u'5437', when=1306338650, category=None, project=u'icephone', repository=u'…redacted/icephone') to database
2011-05-25 11:50:50-0400 [-] WARNING: change source is using deprecated addChange parameter 'who'
2011-05-25 11:50:50-0400 [-] added change Change(who=u'zwest', files=[…redacted…], comments=u'…redacted…', revision=u'5438', when=1306338650, category=None, project=u'icephone', repository=u'…redacted/icephone') to database
2011-05-25 11:50:50-0400 [-] SVNPoller finished polling None
…
2011-05-25 13:46:48-0400 [-] svnPoller: _process_changes 5438 .. 5442
2011-05-25 13:46:48-0400 [-] Adding change revision 5439
2011-05-25 13:46:48-0400 [-] Adding change revision 5440
2011-05-25 13:46:48-0400 [-] Adding change revision 5441
2011-05-25 13:46:48-0400 [-] Adding change revision 5442
2011-05-25 13:46:48-0400 [-] WARNING: change source is using deprecated addChange parameter 'who'
2011-05-25 13:46:48-0400 [-] added change Change(who=u'zwest', files=[…redacted…], comments=u'…redacted…', revision=u'5439', when=1306345608, category=None, project=u'icephone', repository=u'…redacted/icephone') to database
2011-05-25 13:46:48-0400 [-] WARNING: change source is using deprecated addChange parameter 'who'
2011-05-25 13:46:49-0400 [-] added change Change(who=u'zwest', files=[…redacted…], comments=u'…redacted…', revision=u'5440', when=1306345608, category=None, project=u'icephone', repository=u'…redacted/icephone') to database
2011-05-25 13:46:49-0400 [-] WARNING: change source is using deprecated addChange parameter 'who'
2011-05-25 13:46:49-0400 [-] added change Change(who=u'zwest', files=[…redacted…], comments=u'…redacted…', revision=u'5441', when=1306345609, category=None, project=u'icephone', repository=u'…redacted/icephone') to database
2011-05-25 13:46:49-0400 [-] WARNING: change source is using deprecated addChange parameter 'who'
2011-05-25 13:46:49-0400 [-] added change Change(who=u'zwest', files=[…redacted…], comments=u'…redacted…', revision=u'5442', when=1306345609, category=None, project=u'icephone', repository=u'…redacted/icephone') to database
2011-05-25 13:46:49-0400 [-] SVNPoller finished polling None

From the master, at build time:

2011-05-26 07:00:50-0400 [-] ShellCommand.startCommand(cmd=<RemoteCommand 'svn' at 4331438024>)
2011-05-26 07:00:50-0400 [-]   cmd.args = {'username': '…redacted…', 'password': '…redacted…', 'workdir': 'build', 'patch': None, 'retry': None, 'mode': 'update', 'timeout': 1200, 'svnurl': u'…redacted/icephone/branches/icephone-1.10', 'always_purge': None, 'revision': u'5437'}
2011-05-26 07:00:50-0400 [-] <RemoteCommand 'svn' at 4331438024>: RemoteCommand.run [75]
2011-05-26 07:00:50-0400 [-] LoggedRemoteCommand.start
2011-05-26 07:00:51-0400 [-] sending ping
2011-05-26 07:00:51-0400 [Broker,0,127.0.0.1] ping finished: success
2011-05-26 07:01:01-0400 [Broker,0,127.0.0.1] <RemoteCommand 'svn' at 4331438024> rc=0
2011-05-26 07:01:01-0400 [-] closing log <buildbot.status.logfile.LogFile instance at 0x10421e950>
2011-05-26 07:01:01-0400 [-] releaseLocks(<buildbot.steps.source.SVN instance at 0x1038a9830>): []
2011-05-26 07:01:01-0400 [-]  step 'svn' complete: success
…build steps redacted…
2011-05-26 07:53:11-0400 [-]  <Build icephone-stable-nightly>: build finished
2011-05-26 07:53:11-0400 [-]  setting expectations for next time
2011-05-26 07:53:11-0400 [-] new expectations: 3227.62330431 seconds

Changes in build

From the WebStatus output, these are the changes in order. The final one (#31) is the revision it chose to build (r5437):

Change #32

Changed by	zwest
Changed at	Wed 25 May 2011 11:50:50
Repository	…redacted/icephone
Project	icephone
Branch	branches/icephone-1.10
Revision	5438
Comments
…redacted…
Changed files
…redacted

Change #35

Changed by	zwest
Changed at	Wed 25 May 2011 13:46:49
Repository	…redacted/icephone
Project	icephone
Branch	branches/icephone-1.10
Revision	5441
Comments
…redacted…
Changed files
…redacted…

Change #36

Changed by	zwest
Changed at	Wed 25 May 2011 13:46:49
Repository	…redacted/icephone
Project	icephone
Branch	branches/icephone-1.10
Revision	5442
Comments
…redacted…
Changed files
…redacted…

Change #31

Changed by	zwest
Changed at	Wed 25 May 2011 11:50:50
Repository	…redacted/icephone
Project	icephone
Branch	branches/icephone-1.10
Revision	5437
Comments
…redacted…
Changed files
…redacted…

Build Data

Name	Value	Source
branch	branches/icephone-1.10	Build
buildername	icephone-stable-nightly	Builder
buildnumber	5	Build
got_revision	5437	Source
project	icephone	Build
repository	…redacted/icephone	Build
revision	5437	Build
scheduler	icephone-stable-nightly	Scheduler
slavename	QAMacbookPro	BuildSlave
warnings-count	34656	WarningCountingShellCommand?
workdir	/Users/buildbot/bb/slave/icephone-stable-nightly	slave

(How awesome is that warning count?)

Notes

I've stashed away the debug log in case you need more information. Just want to strip away any information that needs redacting, so let me know if you need more.

Change History

comment:1 Changed 2 years ago by dustin

Here's the code in Nightly that's handling this case:

            changeids = sorted(classifications.keys())
            wfd = defer.waitForDeferred(
                    self.addBuildsetForChanges(reason=self.reason, changeids=changeids)) 
            yield wfd 
            wfd.getResult()

so from what I can tell, changeids should be [31,32,35,36] in this case. Then, in source:master/buildbot/schedulers/base.py,

        # attributes for this sourcestamp will be based on the most recent                         
        # change, so fetch the change with the highest id                                          
        d = self.master.db.changes.getChange(max(changeids))                                       
        def chdict2change(chdict):                                                                 
            if not chdict:                                                                         
                return None                                                                        
            return changes.Change.fromChdict(self.master, chdict)                                  
        d.addCallback(chdict2change)                                                               
        def create_sourcestamp(change):                                                            
            return self.master.db.sourcestamps.addSourceStamp(                                     
                    branch=change.branch,                                                          
                    revision=change.revision,                                                      
                    repository=change.repository,                                                  
                    project=change.project,                                                        
                    changeids=changeids)                                                           
        d.addCallback(create_sourcestamp)                                                          
        d.addCallback(self.addBuildsetForSourceStamp, reason=reason,                               
                                external_idstring=external_idstring,                               
                                builderNames=builderNames,                                         
                                properties=properties)                                             
        return d

so max(changeids) there should be 36, not 31.

Can you add some print statements to this code to verify, or to see what's wrong?

comment:2 Changed 2 years ago by dustin

Version changed from 0.8.3p1 to master
Milestone changed from undecided to 0.8.4

comment:3 Changed 2 years ago by zacw

Looks like I can reproduce it by commtting to trunk and the branch (in separate revisions, of course).

Order displayed in WebStatus: [48, 49, 45, 46, 47].
changeids in the timed.py code: [45, 46, 47, 48, 49].
max(changeids) in the base.py code: 49

However, the build was done off 47.

comment:4 Changed 2 years ago by zacw

Browsing around with no idea what I'm looking at,

# fetch change ids
tbl = self.db.model.sourcestamp_changes
q = tbl.select(whereclause=(tbl.c.sourcestampid == ssid))
res = conn.execute(q)
for row in res:
    ssdict['changeids'].add(row.changeid)
res.close()

Does the where clause need to be sorted in some way? I don't know what source stamps are, nor how they interact with anything, but this was the only thing that stuck out.

I can add some debug code if you let me know what values you're interested in and where.

comment:5 Changed 2 years ago by Dustin J. Mitchell

Status changed from new to closed
Resolution set to fixed

Sort changes before creating a SourceStamp? from an ssdict

This includes an improved test - the old test worked by chance.

Fixes #1971.

Changeset: dc3ca6e278c44e9a8a2ca8784ca29d8081a41df1

Note: See TracTickets for help on using tickets.

Download in other formats: