Keepalive forbidden on long-running build steps

[joel@…]

On long build steps, such as checking out a large repository where the checkout is in excess of 1hr (averaging 90 minutes) somewhere through the checkout process the Bitten slave will start reporting errors like:

[WARNING ] Server returned keepalive error 403: Forbidden

Likewise, on the server,

2012-02-21 13:02:16,539 Trac[main] WARNING: HTTPForbidden: 403 Forbidden (BUILD_EXEC privileges are required to perform this operation)

I'm guessing that the authentication token used for the build slave expires and that a new authentication request needs to be made.

[joel@…]

And yes, the slave's log will end like this:

[ERROR ] Exception raised processing step checkout. Reraising HTTP Error 403: Forbidden
[ERROR ] HTTP Error 403: Forbidden
[INFO ] Slave exited at 2012-02-21 12:44:13

[Joel Low <joel@…>]

I've increased the logging level for the build server and this results:

2012-02-23 23:05:59,374 Trac[session] DEBUG: Retrieving session for ID u'Bitten Builder?'
2012-02-23 23:06:00,466 Trac[master] INFO: Slave server build 116 keepalive ("Boost" as of [1244])
2012-02-23 23:06:54,628 Trac[main] DEBUG: Dispatching <Request "POST '/builds/116/keepalive/'"> 2012-02-23 23:06:58,154 Trac[api] INFO: Synchronized '(default)' repository in 3.51 seconds
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing BUILD_EXEC on None
2012-02-23 23:06:59,089 Trac[main] WARNING: HTTPForbidden: 403 Forbidden (BUILD_EXEC privileges are required to perform this operation)
2012-02-23 23:06:59,089 Trac[chrome] DEBUG: Prepare chrome data for request
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing XML_RPC on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing TICKET_VIEW on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing TICKET_CREATE on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing SEARCH_VIEW on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing BUILD_VIEW on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing BUILD_ADMIN on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing BUILD_MODIFY on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing TRAC_ADMIN on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing PERMISSION_GRANT on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing PERMISSION_REVOKE on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing TICKET_ADMIN on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing MILESTONE_VIEW on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing VERSIONCONTROL_ADMIN on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing REPORT_VIEW on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing ROADMAP_VIEW on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing TIMELINE_VIEW on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing BROWSER_VIEW on None
2012-02-23 23:06:59,089 Trac[perm] DEBUG: No policy allowed anonymous performing WIKI_VIEW on <Resource 'wiki'>
2012-02-23 23:06:59,183 Trac[perm] DEBUG: No policy allowed anonymous performing EMAIL_VIEW on None

What precedes are plenty of keepalive requests. This is the first one that fails. Hope this helps isolate the problem.

[Joel Low <joel@…>]

It turns out setting auth_check_ip in trac.ini to false fixes the problem.

I've traced this and it seems to be caused by the fact that both server and client are dual-stack ipv4/ipv6 and the initial request starts on ipv4 and the later keepalive requests go on ipv6, which fail (or vice versa).

I'm not sure what is the best way forward, or why this only manifests after (usually exactly) 1 hour of execution, though for this particular Trac environment I've disabled auth_check_ip.

I'll leave this ticket open since I'm not sure if this problem may need a targeted fix, and especially since on a public Trac environment auth_check_ip is a security feature worth enabling.