{"action":"created","issue":{"url":"https://api.github.com/repos/cfengine/core/issues/2499","repository_url":"https://api.github.com/repos/cfengine/core","labels_url":"https://api.github.com/repos/cfengine/core/issues/2499/labels{/name}","comments_url":"https://api.github.com/repos/cfengine/core/issues/2499/comments","events_url":"https://api.github.com/repos/cfengine/core/issues/2499/events","html_url":"https://github.com/cfengine/core/pull/2499","id":134818905,"number":2499,"title":"Redmine #7933: Fix timing bug when grabbing global package lock.","user":{"login":"kacf","id":4037094,"avatar_url":"https://avatars.githubusercontent.com/u/4037094?v=3","gravatar_id":"","url":"https://api.github.com/users/kacf","html_url":"https://github.com/kacf","followers_url":"https://api.github.com/users/kacf/followers","following_url":"https://api.github.com/users/kacf/following{/other_user}","gists_url":"https://api.github.com/users/kacf/gists{/gist_id}","starred_url":"https://api.github.com/users/kacf/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kacf/subscriptions","organizations_url":"https://api.github.com/users/kacf/orgs","repos_url":"https://api.github.com/users/kacf/repos","events_url":"https://api.github.com/users/kacf/events{/privacy}","received_events_url":"https://api.github.com/users/kacf/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2016-02-19T09:44:02Z","updated_at":"2016-02-19T10:08:42Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/cfengine/core/pulls/2499","html_url":"https://github.com/cfengine/core/pull/2499","diff_url":"https://github.com/cfengine/core/pull/2499.diff","patch_url":"https://github.com/cfengine/core/pull/2499.patch"},"body":"Normally, when CFEngine grabs a promise lock, that exact lock is not\r\nexpected to be grabbed again for the duration of the cf-agent run. And\r\nin fact, this is made impossible by the promise lock cache (see\r\nEvalContextPromiseLockCacheContains()). If a promise is in fact\r\nreevaluated, it is always because some part of the promise has\r\nchanged, even something as simple as the promise comment. This alters\r\nthe lock name, and hence it will count as a new lock. This behavior\r\nsometimes requires specific workarounds to rerun promises inside\r\noften-used bundles.\r\n\r\nHowever, the global package lock works a bit differently: Since we\r\nwant to it to be a truly global lock, we need to reuse it. The first\r\nstep in this process is to remove it from the promise lock cache. This\r\nis already done.\r\n\r\nHowever, we run into a subtle issue when it comes to `ifelapsed`\r\nvalues: `ifelapsed` is set to zero in the global package lock in order\r\nfor timing not to get in the way. But the logic in locks.c to deal\r\nwith ifelapsed is a bit flawed: The time counted as \"now\" is the start\r\ntime of cf-agent, but the time recorded as \"last time this lock was\r\nused\" is the actual current time, which means that from the\r\nperspective of \"now\", the last used time of the lock may be in the\r\nfuture. This causes strange effects when cf-agent has been executing\r\nfor more than a minute, `elapsedtime` inside `AcquireLock` turns\r\nnegative, and this causes CFEngine to think that another agent is\r\nexecuting and it skips grabbing the lock altogether.\r\n\r\nAnd this is okay for locks with a nonzero ifelapsed value, since they\r\nare not generally expected to be executed more than once inside one\r\ncf-agent run, or when mutiple agents are executing in parallel, even\r\nif the value is 1, and that run takes longer than one minute.\r\n\r\nBut for `ifelapsed == 0`, this check doesn't make sense because such\r\nlocks should be grabbed regardless of whether it was grabbed before,\r\nor whether other agents have executed the same promise. Note that we\r\nare still protected against executing the same promise *at the same\r\ntime*, this only introduces the capability to grab a promise lock that\r\nwas executed earlier in the same run, or earlier by a different agent.\r\n\r\nEffects this has on the locks:\r\n\r\n* Executing the same promise concurrently:\r\n  NO (no change). You still cannot grab a currently held lock.\r\n\r\n* Executing the exact same promise twice in the same run:\r\n  NO (no change). If you got to the `elapsedtime` check this might\r\n  happen, but we never get there because the promise lock cache will\r\n  exit from the function early.\r\n\r\n* Executing the exact same promise in concurrent agents with\r\n  `ifelapsed >= 1`:\r\n  NO (no change). For `ifelapsed >= 0` the logic is unchanged.\r\n\r\n* Executing the exact same promise in concurrent agents with\r\n  `ifelapsed == 0`:\r\n  YES (CHANGED). This can now happen, since we don't check if another\r\n  agent has executed the promise. I believe this is perfectly okay and\r\n  even expected, since `ifelapsed == 0`.\r\n\r\n* Grabbing the exact same promise lock twice in the same run, if lock\r\n  is removed from promise lock cache and `ifelapsed == 0`:\r\n  YES (CHANGED). Currently *only* the global package lock does this,\r\n  and it is a requirement for it to work correctly. This case is what\r\n  the bugfix is about, the others are just possible side effects.\r\n\r\nChangelog: Fix a bug which sometimes caused package promises to be\r\nskipped with \"XX Another cf-agent seems to have done this since I\r\nstarted\" messages in the log, most notably in long running cf-agent\r\nruns (longer than one minute)."},"comment":{"url":"https://api.github.com/repos/cfengine/core/issues/comments/186148196","html_url":"https://github.com/cfengine/core/pull/2499#issuecomment-186148196","issue_url":"https://api.github.com/repos/cfengine/core/issues/2499","id":186148196,"user":{"login":"kacf","id":4037094,"avatar_url":"https://avatars.githubusercontent.com/u/4037094?v=3","gravatar_id":"","url":"https://api.github.com/users/kacf","html_url":"https://github.com/kacf","followers_url":"https://api.github.com/users/kacf/followers","following_url":"https://api.github.com/users/kacf/following{/other_user}","gists_url":"https://api.github.com/users/kacf/gists{/gist_id}","starred_url":"https://api.github.com/users/kacf/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kacf/subscriptions","organizations_url":"https://api.github.com/users/kacf/orgs","repos_url":"https://api.github.com/users/kacf/repos","events_url":"https://api.github.com/users/kacf/events{/privacy}","received_events_url":"https://api.github.com/users/kacf/received_events","type":"User","site_admin":false},"created_at":"2016-02-19T10:08:42Z","updated_at":"2016-02-19T10:08:42Z","body":"@pasinskim, @jimis: It would be great if you could take a quick look at this. The diff is small, but the reasons are somewhat complicated."}}