Perforce VCS - Fatal client error; disconnecting! - p4tickets.txt: Access is denied

We are using TeamCity with Perforce. We have multiple Perforce VCS roots (~60). We are getting regular (every 30-60s) errors in the teamcity-vcs.log similar to:

-----
[2015-05-29 10:49:00,554]  DEBUG [cal executor 10] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:1666 changes -m 1 -s submitted
[2015-05-29 10:49:00,554]   INFO [cal executor 14] -      jetbrains.buildServer.VCS - Cannot load current state for VCS root "project_main" {instance id=229, parent internal id=37, parent id=Project_ProjectBuilds_ProjectMain, description: "perforce: server:1666"}: Fatal client error; disconnecting!
chmod: C:\Users\username\p4tickets.txt: Access is denied.

[2015-05-29 10:49:00,554]  DEBUG [cal executor 14] -      jetbrains.buildServer.VCS - Fatal client error; disconnecting!
chmod: C:\Users\username\p4tickets.txt: Access is denied.

jetbrains.buildServer.vcs.VcsRootVcsException: Fatal client error; disconnecting!
chmod: C:\Users\username\p4tickets.txt: Access is denied.

    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector.createRootException(VcsChangesStatesCollector.java:49)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector.getCurrentState(VcsChangesStatesCollector.java:14)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector.access$100(VcsChangesStatesCollector.java:22)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector$2.run(VcsChangesStatesCollector.java:1)
    at jetbrains.buildServer.util.NamedThreadFactory.executeWithNewThreadName(NamedThreadFactory.java:102)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector.doCollectStates(VcsChangesStatesCollector.java:29)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector.access$000(VcsChangesStatesCollector.java:7)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector$1.run(VcsChangesStatesCollector.java:2)
    at jetbrains.buildServer.vcs.impl.VcsChangesLoaderImpl$ImmediateFutureExecService$1.call(VcsChangesLoaderImpl.java:2)
    at jetbrains.buildServer.serverSide.impl.ImmediateFuture.get(ImmediateFuture.java:46)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector.collectStatesForAllRoots(VcsChangesStatesCollector.java:20)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector.getCurrentStateSnapshot(VcsChangesStatesCollector.java:34)
    at jetbrains.buildServer.vcs.impl.VcsChangesFetcher.loadChangesNoLocking(VcsChangesFetcher.java:38)
    at jetbrains.buildServer.vcs.impl.VcsChangesSyncFetcher.loadChangesNoLocking(VcsChangesSyncFetcher.java:22)
    at jetbrains.buildServer.vcs.impl.VcsChangesLoaderImpl.tryLoadChanges(VcsChangesLoaderImpl.java:54)
    at jetbrains.buildServer.serverSide.impl.VcsModificationChecker$1$1.run(VcsModificationChecker.java:17)
    at jetbrains.buildServer.util.NamedThreadFactory.executeWithNewThreadName(NamedThreadFactory.java:102)
    at jetbrains.buildServer.serverSide.impl.VcsModificationChecker$1.run(VcsModificationChecker.java:3)
    at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)
Caused by: jetbrains.buildServer.vcs.VcsException: Fatal client error; disconnecting!
chmod: C:\Users\username\p4tickets.txt: Access is denied.

    at jetbrains.buildServer.vcs.perforce.PerforceConnection.runCommand(PerforceConnection.java:318)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection.tryToLogin(PerforceConnection.java:352)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection.runCommand(PerforceConnection.java:304)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection.runCommand(PerforceConnection.java:356)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection.access$000(PerforceConnection.java:40)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection$2.getNewValue(PerforceConnection.java:487)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection$2.getNewValue(PerforceConnection.java:483)
    at jetbrains.buildServer.util.UptodateValue.getValue(UptodateValue.java:65)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection.getCurrentChangesCommandOutput(PerforceConnection.java:508)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection.runGetCurrentVersionCommand(PerforceConnection.java:458)
    at jetbrains.buildServer.vcs.perforce.PerforceConnection.getCurrentVersion(PerforceConnection.java:453)
    at jetbrains.buildServer.vcs.perforce.PerforceChangesCollector.getCurrentVersion(PerforceChangesCollector.java:35)
    at jetbrains.vcs.api.services.impl.RepositoryStateServiceProvider$1.getCurrentState(RepositoryStateServiceProvider.java:7)
    at jetbrains.buildServer.vcs.impl.VcsRootInstanceImpl.getCurrentState(VcsRootInstanceImpl.java:43)
    at jetbrains.buildServer.vcs.impl.VcsChangesStatesCollector.getCurrentState(VcsChangesStatesCollector.java:8)
    ... 21 more
-----

The p4tickets.txt file in question is being written to fairly constantly, every minute or so, containing tickets for connecting to our various servers.

It appears that TC is constantly logging in every minute or so, and is doing so for each server we have a VCS root for, often within milliseconds of each other.

-----
[2015-05-29 10:48:20,237]  DEBUG [ical executor 5] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
[2015-05-29 10:48:20,243]  DEBUG [cal executor 15] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:49:00,341]  DEBUG [cal executor 12] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:49:00,343]  DEBUG [cal executor 14] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:49:00,348]  DEBUG [ical executor 7] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:49:00,351]  DEBUG [cal executor 10] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:49:30,433]  DEBUG [cal executor 12] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:49:30,436]  DEBUG [ical executor 5] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
[2015-05-29 10:50:10,493]  DEBUG [ical executor 2] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:50:10,498]  DEBUG [cal executor 13] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:50:10,499]  DEBUG [ical executor 3] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:50:10,501]  DEBUG [cal executor 11] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:50:40,618]  DEBUG [cal executor 10] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:50:40,621]  DEBUG [ical executor 7] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
[2015-05-29 10:51:20,693]  DEBUG [cal executor 13] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:51:20,696]  DEBUG [ical executor 3] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:51:20,699]  DEBUG [ical executor 7] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:51:20,701]  DEBUG [cal executor 11] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:51:50,764]  DEBUG [cal executor 10] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:51:50,769]  DEBUG [cal executor 14] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
[2015-05-29 10:52:30,855]  DEBUG [cal executor 10] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:52:30,862]  DEBUG [ical executor 7] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:52:30,865]  DEBUG [cal executor 11] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:52:30,868]  DEBUG [ical executor 2] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:53:00,884]  DEBUG [cal executor 12] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
[2015-05-29 10:53:00,886]  DEBUG [cal executor 13] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:53:40,977]  DEBUG [ical executor 5] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:53:40,996]  DEBUG [cal executor 13] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:53:40,999]  DEBUG [cal executor 10] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:53:41,002]  DEBUG [ical executor 2] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:54:11,064]  DEBUG [cal executor 11] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:54:11,069]  DEBUG [ical executor 7] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
[2015-05-29 10:54:41,126]  DEBUG [cal executor 15] -   jetbrains.buildServer.VCS.P4 - run p4 -u username2 -p server2:2011 login
[2015-05-29 10:54:51,146]  DEBUG [cal executor 10] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:54:51,147]  DEBUG [cal executor 11] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:54:51,149]  DEBUG [ical executor 7] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:54:51,157]  DEBUG [cal executor 14] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:55:21,194]  DEBUG [cal executor 11] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
[2015-05-29 10:55:21,199]  DEBUG [cal executor 10] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:56:01,312]  DEBUG [cal executor 12] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:56:01,316]  DEBUG [ical executor 2] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:56:01,320]  DEBUG [cal executor 11] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:56:01,322]  DEBUG [ical executor 7] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:56:31,371]  DEBUG [cal executor 13] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:56:31,374]  DEBUG [cal executor 14] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
[2015-05-29 10:57:11,463]  DEBUG [cal executor 15] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2004 login
[2015-05-29 10:57:11,477]  DEBUG [ical executor 5] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:57:11,613]  DEBUG [ical executor 2] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server2:2011 login
[2015-05-29 10:57:41,574]  DEBUG [cal executor 15] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2015 login
[2015-05-29 10:57:41,575]  DEBUG [ical executor 3] -   jetbrains.buildServer.VCS.P4 - run p4 -u username -p server:2016 login
-----

My analysis of this is that because the p4 executable is being run in quick succession, when it attempts to write p4tickets.txt it cannot due to another p4 process writing to it as well, so it fails. I've searched on these forums and online, I couldn't find any mention of this problem. Are we doing something wrong? Is there any way to stop TC querying p4 in quick succession like this?

Thanks,
David

3 comments
Comment actions Permalink

Hello David,

  Thanks for writing us about this problem. You're right, we haven't met such a problem previously, so this is why you haven't seen it before.

   TeamCity runs p4 login command only when in the following situations:

   - when a command like 'p4 changes' indicate that this ticket is not valid and the user is not authenticated
   - always when a server-side patch is created (on the build start)

   TeamCity doesn't run p4 login if you don't specify the password in VCS Root settings and run p4 login outside TeamCity (i.e. you handle Perforce authentication outside TeamCity).

   For further investigation, please create an issue in our issue tracker at https://youtrack.jetbrains.com/newIssue?project=TW&clearDraft=true&c=Assignee+maxkir&c=Subsystem+Version+Control%3A+Perforce

   Also, please enable debug-vcs logging preset, as described here: https://confluence.jetbrains.com/display/TCD9/TeamCity+Server+Logs#TeamCityServerLogs-LoggingrelatedDiagnosticsUI
   and attach logs to the issue after reproducing the problem (you can limit the visibility of the attached logs).

   Thanks,
   KIR

0
Comment actions Permalink

With help from the above response, we determined what the cause of the problem was.

Our Perforce setup is as follows:

  • One "P4Auth" server, handling user credentials
  • Multiple off-site hosted Perforce servers
  • Multiple (but fewer than 1-to-1) on-site broker/proxies pointing at the off-site servers


Our issue was due to getting a different ticket when logging in depending on whether connecting to an on-site broker/proxy or the off-site server directly. Even connecting to the same P4 server, once directly and once via the broker/proxy lead to a different ticket being generated. We suspect this may be due to IPv4/v6 differences (we connect to our on-site broker/proxy via IPv4 but the off-site servers via IPv6) being incorporated into the hashing algorithm used to generate the ticket.

The result of this was that some of our VCS roots pointed to off-site servers directly (the ones that had no broker/proxy on-site) and others pointed to the on-site broker/proxies. When logging into either on- or off- site servers, the ticket generated would change and thus flip-flop between two different values. When connecting to an on-site server after previously connecting to an off-site server, the ticket would be invalid and would need re-authentication.

Our fix was to spin up brokers on-site for all the remaining off-site servers we were connecting directly to, and ensure all our VCS roots pointed at the new on-site brokers. Since then we've had no "access denied" errors (fix has been in for a few days now).

Perforce support have been contacted to point out this problem and we're waiting to hear back on a fix or workaround. Initial reaction seems to be that "that shouldn't happen", so hopefully a fix will be forthcoming.

0
Comment actions Permalink

Hello David,

  Thanks a lot for the follow-up. I'm glad the problem is resolved now, and hope won't appear again.

  Best regards,
  KIR

0

Please sign in to leave a comment.