{"thread":{"id":"50411","subject":"Weird (seemingly flakey) p4 breakage in t9833","startedAt":"2019-02-06T10:33:27Z","lastAt":"2019-02-06T13:56:04Z","messageCount":4,"participants":["Johannes Schindelin","SZEDER Gábor","Luke Diamand"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"368574","messageId":"nycvar.QRO.7.76.6.1902061004110.41@tvgsbejvaqbjf.bet","threadId":"50411","inReplyTo":null,"subject":"Weird (seemingly flakey) p4 breakage in t9833","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2019-02-06T10:33:21Z","receivedAt":"2019-02-06T10:33:27Z","isPatch":false,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Luke,\n\nin a private Azure Pipeline (sorry...) I noticed an intermittent problem\nin the p4 tests on osx-gcc.\n\nI would point you to a public log, but the Azure Pipelines support *just*\nmade it to next, so I *just* set up a public one targeting anything else\nthan my `vsts-ci` branch, at\nhttps://dev.azure.com/gitgitgadget/git/_build/index?definitionId=6. And\nthose builds do not show that problem, so it must be a flakey test.\n\nBut maybe you can spot anything familiar from the log?\n\n-- snip --\n[...]\n++ P4TICKETS='/Users/vsts/agent/2.146.0/work/1/s/t/trash\ndirectory.t9833-errors/cli/tickets'\n++ P4USER=short_expiry_user\n++ echo password\n++ p4 login\nEnter password: \nUser short_expiry_user logged in.\nPerforce db files in '.' will be created if missing...\n++ cd '/Users/vsts/agent/2.146.0/work/1/s/t/trash\ndirectory.t9833-errors/git'\n++ git p4 sync\n++ true\n+++ time_in_seconds\n+++ cd /\n+++ /usr/bin/python -c 'import time; print(int(time.time()))'\n++ test 1549411312 -gt 1549411605\n++ sleep 1\nPerforce db files in '.' will be created if missing...\nfailure accessing depot: perforce ticket expires in 1 seconds\nPerforming incremental import into refs/remotes/p4/master git branch\nDepot paths: //depot/\nerror: last command exited with $?=1\n++ true\n+++ time_in_seconds\n+++ cd /\n+++ /usr/bin/python -c 'import time; print(int(time.time()))'\n++ test 1549411314 -gt 1549411605\n++ sleep 1\nnot ok 6 - git operation with expired ticket\n#\t\n#\t\tP4TICKETS=\"$cli/tickets\" &&\n#\t\tP4USER=short_expiry_user &&\n#\t\techo \"password\" | p4 login &&\n#\t\t(\n#\t\t\tcd \"$git\" &&\n#\t\t\tgit p4 sync &&\n#\t\t\tsleep 5 &&\n#\t\t\ttest_must_fail git p4 sync 2>errmsg &&\n#\t\t\tgrep \"failure accessing depot\" errmsg\n#\t\t)\n#\t\n-- snap --\n\nBTW I find it very odd to see a `sleep 1` in the trace but not in the\nsnippet (there is only a `sleep 5` instead, which I fail to see in the\ntrace). Odd?\n\nCiao,\nJohannes\n"},{"id":"368580","messageId":"20190206111111.GK10587@szeder.dev","threadId":"50411","inReplyTo":"nycvar.QRO.7.76.6.1902061004110.41@tvgsbejvaqbjf.bet","subject":"Re: Weird (seemingly flakey) p4 breakage in t9833","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-02-06T11:11:11Z","receivedAt":"2019-02-06T11:11:25Z","isPatch":false,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Wed, Feb 06, 2019 at 11:33:21AM +0100, Johannes Schindelin wrote:\n> Hi Luke,\n> \n> in a private Azure Pipeline (sorry...) I noticed an intermittent problem\n> in the p4 tests on osx-gcc.\n> \n> I would point you to a public log, but the Azure Pipelines support *just*\n> made it to next, so I *just* set up a public one targeting anything else\n> than my `vsts-ci` branch, at\n> https://dev.azure.com/gitgitgadget/git/_build/index?definitionId=6. And\n> those builds do not show that problem, so it must be a flakey test.\n> \n> But maybe you can spot anything familiar from the log?\n> \n> -- snip --\n> [...]\n> ++ P4TICKETS='/Users/vsts/agent/2.146.0/work/1/s/t/trash\n> directory.t9833-errors/cli/tickets'\n> ++ P4USER=short_expiry_user\n> ++ echo password\n> ++ p4 login\n> Enter password: \n> User short_expiry_user logged in.\n> Perforce db files in '.' will be created if missing...\n> ++ cd '/Users/vsts/agent/2.146.0/work/1/s/t/trash\n> directory.t9833-errors/git'\n> ++ git p4 sync\n> ++ true\n> +++ time_in_seconds\n> +++ cd /\n> +++ /usr/bin/python -c 'import time; print(int(time.time()))'\n> ++ test 1549411312 -gt 1549411605\n> ++ sleep 1\n> Perforce db files in '.' will be created if missing...\n> failure accessing depot: perforce ticket expires in 1 seconds\n> Performing incremental import into refs/remotes/p4/master git branch\n> Depot paths: //depot/\n> error: last command exited with $?=1\n> ++ true\n> +++ time_in_seconds\n> +++ cd /\n> +++ /usr/bin/python -c 'import time; print(int(time.time()))'\n> ++ test 1549411314 -gt 1549411605\n> ++ sleep 1\n> not ok 6 - git operation with expired ticket\n> #\t\n> #\t\tP4TICKETS=\"$cli/tickets\" &&\n> #\t\tP4USER=short_expiry_user &&\n> #\t\techo \"password\" | p4 login &&\n> #\t\t(\n> #\t\t\tcd \"$git\" &&\n> #\t\t\tgit p4 sync &&\n> #\t\t\tsleep 5 &&\n> #\t\t\ttest_must_fail git p4 sync 2>errmsg &&\n> #\t\t\tgrep \"failure accessing depot\" errmsg\n> #\t\t)\n> #\t\n> -- snap --\n\nI saw this on Travis CI a couple of times, and looked into it, though\nI have no idea how p4 is supposed to work...  anyway, my theory is:\n\nThe previous test 'create group with short ticket expiry' creates a\n\"ticket\" with 3 seconds expiration time, to be used in this failing\none.  This timeout might be just a bit too short when running the test\nunder high load, and it takes long enough to reach the first 'git p4\nsync', so long that the timeout is (almost?) up, and then 'git p4'\nerrors out.\n\nI'm not sure what the proper solution would be (assuming that my\ntheory is right, that is): increasing the ticket timeout to a \"must be\nsurely long enough\" value would require longer 'sleep' in this test,\nwhich is not good.  I wonder why that failing 'git p4 sync' is\nnecessary in the first place, and whether it's really necessary to\ntest ticket expiration, but then again: I have no idea how p4 works.\n\nOn a related note, I think it would be better if these two tests were\nsquashed into one, so we would get the whole picture.\n\n> BTW I find it very odd to see a `sleep 1` in the trace but not in the\n> snippet (there is only a `sleep 5` instead, which I fail to see in the\n> trace). Odd?\n\nIntentional.  p4d seems to be prone to hang, to circumvent this\nstart_p4d() from 'lib-git-p4.sh' starts a watchdog process in the\nbackground to kill it after a long-enough timeout is up.  These three\nlines in the log:\n\n> +++ /usr/bin/python -c 'import time; print(int(time.time()))'\n> ++ test 1549411312 -gt 1549411605\n> ++ sleep 1\n\ncome from that background process.\n\nA couple of cleanup patches on top of your 'test_atexit' will\neventually get rid of it...  once I get around to clean them up :)\n"},{"id":"368583","messageId":"CAE5ih7_s+GZo10DMkhbkfoRPGovHZZo8q3qBaPKq8_uDdxrX0Q@mail.gmail.com","threadId":"50411","inReplyTo":"20190206111111.GK10587@szeder.dev","subject":"Re: Weird (seemingly flakey) p4 breakage in t9833","fromName":"Luke Diamand","fromEmail":"luke@diamand.org","sentAt":"2019-02-06T11:54:38Z","receivedAt":"2019-02-06T11:54:52Z","isPatch":false,"sender":{"key":"luke@diamand.org","avatar":"https://avatars.githubusercontent.com/u/5330967?v=4"},"body":"On Wed, 6 Feb 2019 at 11:11, SZEDER Gábor <szeder.dev@gmail.com> wrote:\n>\n> On Wed, Feb 06, 2019 at 11:33:21AM +0100, Johannes Schindelin wrote:\n> > Hi Luke,\n> >\n> > in a private Azure Pipeline (sorry...) I noticed an intermittent problem\n> > in the p4 tests on osx-gcc.\n> >\n> > I would point you to a public log, but the Azure Pipelines support *just*\n> > made it to next, so I *just* set up a public one targeting anything else\n> > than my `vsts-ci` branch, at\n> > https://dev.azure.com/gitgitgadget/git/_build/index?definitionId=6. And\n> > those builds do not show that problem, so it must be a flakey test.\n> >\n> > But maybe you can spot anything familiar from the log?\n\nI think you're right - it's 'git operation with expired ticket'.\n\nI wonder if we could make a faked-up Perforce client which returned\nthe correct error data - then it wouldn't need to wait at all.\n\nOr we could just remove it (or make it optional based on an\nenvironment variable).\n\nLet me know which you think is best and I'll put together a patch.\n\nLuke\n"},{"id":"368589","messageId":"nycvar.QRO.7.76.6.1902061454220.41@tvgsbejvaqbjf.bet","threadId":"50411","inReplyTo":"20190206111111.GK10587@szeder.dev","subject":"Re: Weird (seemingly flakey) p4 breakage in t9833","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2019-02-06T13:55:59Z","receivedAt":"2019-02-06T13:56:04Z","isPatch":false,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Gábor,\n\nOn Wed, 6 Feb 2019, SZEDER Gábor wrote:\n\n> On Wed, Feb 06, 2019 at 11:33:21AM +0100, Johannes Schindelin wrote:\n> \n> > in a private Azure Pipeline (sorry...) I noticed an intermittent problem\n> > in the p4 tests on osx-gcc.\n> > \n> > I would point you to a public log, but the Azure Pipelines support *just*\n> > made it to next, so I *just* set up a public one targeting anything else\n> > than my `vsts-ci` branch, at\n> > https://dev.azure.com/gitgitgadget/git/_build/index?definitionId=6. And\n> > those builds do not show that problem, so it must be a flakey test.\n> > \n> > But maybe you can spot anything familiar from the log?\n> > \n> > -- snip --\n> > [...]\n> > ++ P4TICKETS='/Users/vsts/agent/2.146.0/work/1/s/t/trash\n> > directory.t9833-errors/cli/tickets'\n> > ++ P4USER=short_expiry_user\n> > ++ echo password\n> > ++ p4 login\n> > Enter password: \n> > User short_expiry_user logged in.\n> > Perforce db files in '.' will be created if missing...\n> > ++ cd '/Users/vsts/agent/2.146.0/work/1/s/t/trash\n> > directory.t9833-errors/git'\n> > ++ git p4 sync\n> > ++ true\n> > +++ time_in_seconds\n> > +++ cd /\n> > +++ /usr/bin/python -c 'import time; print(int(time.time()))'\n> > ++ test 1549411312 -gt 1549411605\n> > ++ sleep 1\n> > Perforce db files in '.' will be created if missing...\n> > failure accessing depot: perforce ticket expires in 1 seconds\n> > Performing incremental import into refs/remotes/p4/master git branch\n> > Depot paths: //depot/\n> > error: last command exited with $?=1\n> > ++ true\n> > +++ time_in_seconds\n> > +++ cd /\n> > +++ /usr/bin/python -c 'import time; print(int(time.time()))'\n> > ++ test 1549411314 -gt 1549411605\n> > ++ sleep 1\n> > not ok 6 - git operation with expired ticket\n> > #\t\n> > #\t\tP4TICKETS=\"$cli/tickets\" &&\n> > #\t\tP4USER=short_expiry_user &&\n> > #\t\techo \"password\" | p4 login &&\n> > #\t\t(\n> > #\t\t\tcd \"$git\" &&\n> > #\t\t\tgit p4 sync &&\n> > #\t\t\tsleep 5 &&\n> > #\t\t\ttest_must_fail git p4 sync 2>errmsg &&\n> > #\t\t\tgrep \"failure accessing depot\" errmsg\n> > #\t\t)\n> > #\t\n> > -- snap --\n> \n> I saw this on Travis CI a couple of times, and looked into it, though\n> I have no idea how p4 is supposed to work...  anyway, my theory is:\n> \n> The previous test 'create group with short ticket expiry' creates a\n> \"ticket\" with 3 seconds expiration time, to be used in this failing\n> one.  This timeout might be just a bit too short when running the test\n> under high load, and it takes long enough to reach the first 'git p4\n> sync', so long that the timeout is (almost?) up, and then 'git p4'\n> errors out.\n\nThat sounds very plausible to me, thank you for the analysis!\n\n> I'm not sure what the proper solution would be (assuming that my\n> theory is right, that is): increasing the ticket timeout to a \"must be\n> surely long enough\" value would require longer 'sleep' in this test,\n> which is not good.  I wonder why that failing 'git p4 sync' is\n> necessary in the first place, and whether it's really necessary to\n> test ticket expiration, but then again: I have no idea how p4 works.\n> \n> On a related note, I think it would be better if these two tests were\n> squashed into one, so we would get the whole picture.\n\nAgreed.\n\n> > BTW I find it very odd to see a `sleep 1` in the trace but not in the\n> > snippet (there is only a `sleep 5` instead, which I fail to see in the\n> > trace). Odd?\n> \n> Intentional.  p4d seems to be prone to hang, to circumvent this\n> start_p4d() from 'lib-git-p4.sh' starts a watchdog process in the\n> background to kill it after a long-enough timeout is up.\n\nWhat I found odd was that I did not see that `sleep 1` at all in the\ntrace, but now it makes sense.\n\n> These three lines in the log:\n> \n> > +++ /usr/bin/python -c 'import time; print(int(time.time()))'\n> > ++ test 1549411312 -gt 1549411605\n> > ++ sleep 1\n> \n> come from that background process.\n> \n> A couple of cleanup patches on top of your 'test_atexit' will\n> eventually get rid of it...  once I get around to clean them up :)\n\nHeh, so there *will* be something useful coming out of that aborted side\ntrack? Great!\n\nThank you,\nDscho"}]}