Build no longer triggering (Maybe running too bleeding edge?)

[jimmypuckett]

We have been using the hook for a while & is has been great. In the last few days we have done some upgrades (os patches, gitlab 6.0.0.pre, jenkins 1.526, etc). Anyhow, the automatic building stopped working & we assumed that it was some update we did. I just noticed this in the logs...

{
  "before"=>"<sha 1>",
  "after"=>"<sha 2>",
  "ref"=>"refs/heads/develop",
  "user_id"=>2,
  "user_name"=>"Jimmy Puckett",
  "repository"=>{
    "name"=>"<repository>",
    "url"=>"<user>@<git server>:<group>/<repository>.git",
    "description"=>"",
    "homepage"=>"https://<git server>/<group>/<repository>"
  },
  "commits"=>[
    {
      "id"=>"<commit>",
      "message"=>"<The message>",
      "timestamp"=>"2013-08-06T06:31:42-04:00",
      "url"=>"https://<git server>/<group>/<repository>/commit/<commit>",
      "author"=>{
        "name"=>"Jimmy Puckett",
        "email"=>"<email>"
      }
    },
    {
      "id"=>"<sha 2>",
      "message"=>"<The message>",
      "timestamp"=>"2013-08-06T06:34:05-04:00",
      "url"=>"https://<git server>/<group>/<repository>/commit/<sha 2>",
      "author"=>{
        "name"=>"Jimmy Puckett",
        "email"=>"<email>"
      }
    }
  ],
  "total_commits_count"=>2
}

For some reason (maybe I just don't know what I am looking at?), there are '=>' between the key/value pairs instead of ':'. I would think that it should be...

{
  "before": "<sha 1>",
  "after": "<sha 2>",
  "ref": "refs/heads/develop",
  "user_id": 2,
  "user_name": "Jimmy Puckett",
  "repository": {
    "name": "<repository>",
    "url": "<user>@<git server>:<group>/<repository>.git",
    "description": "",
    "homepage": "https://<git server>/<group>/<repository>"
  },
  "commits": [
    {
      "id": "<commit>",
      "message": "<The message>",
      "timestamp": "2013-08-06T06:31:42-04:00",
      "url": "https://<git server>/<group>/<repository>/commit/<commit>",
      "author": {
        "name": "Jimmy Puckett",
        "email": "<email>"
      }
    },
    {
      "id": "<sha 2>",
      "message": "<The message>",
      "timestamp": "2013-08-06T06:34:05-04:00",
      "url": "https://<git server>/<group>/<repository>/commit/<sha 2>",
      "author": {
        "name": "Jimmy Puckett",
        "email": "<email>"
      }
    }
  ],
  "total_commits_count": 2
}

The odd part is that I then see this in the log...

...
Aug 06, 2013 6:18:08 AM INFO sun.reflect.NativeMethodAccessorImpl invoke0
project <project> matches the develop branch
Aug 06, 2013 6:18:08 AM SEVERE sun.reflect.NativeMethodAccessorImpl invoke0
...

so I guess that means that you can use the '=>' separator? Anyhow, do you have any ideas on where to start looking?

[elvanja]

The "=>" is a Ruby interpretation of JSON so that is not the issue.
It is represented as a Hash and that is the default to_s output.

As for the other log info, it comes from toString() implementation of the Jenkins hudson.model.AbstractProject class. Don't know why you seem to be getting the project name as "". The "<" and ">" are a suspect.

Did you change sensitive info in the payload or was it received just like you pasted it?
E.g. "name": "" is a suspect too. I would expect Gitlab payload to put the project name here.
The same goes for the URL, since I expect it to contain the exact repo url, which is matched against the Jenkins project Git SCM URL, and it has to match exactly. See https://github.com/elvanja/jenkins-gitlab-hook-plugin#hook-data-related or previous issues with examples of real payloads people submitted.

Could it be that the new Gitlab version is sending the payload with different data than before?

[jimmypuckett]

Thanks, as you can guess, I don't do anything with Ruby. As for the "<project>", I am sorry that I should have been more clear that I have sanitized the data that I posted. The log shows the correct project name in the log. I did not change anything other than the sanitizing the values by replacing the live data with "<something>", and inserting whitespace for making it easier to read.

[elvanja]

OK, so the situation is like this.
The "project matches the develop branch" means that there is a Jenkins project that matches the Gitlab payload. It also means the project .

From then on, the plugin tries to trigger the build or notify commit, depending on the hook URL you gave Gitlab.

The payload should then trigger the build if Jenkins project is set not to ignore the notify commit and is buildable (e.g. not new and not disabled). In case of notify commit hook, the schedulePolling method is called on the Jenkins class/project. In case of build now hook, the scheduleBuild2 method is called. In both cases, the plugin expects true to be returned from Jenkins if the trigger was successful. All of the actions are logged, e.g. for build now hook the relevant code is here.

You should be able to see in logs some more details that come after the "project matches the develop branch" line. Can you try and locate all of the log details?

[jimmypuckett]

Here is the entire log from jenkins when a submit happened on gitlab...

Aug 06, 2013 6:18:08 AM INFO sun.reflect.NativeMethodAccessorImpl invoke0
gitlab web hook triggered for repo url gitlab@<git server>:<group>/<repository>.git and develop branch
Aug 06, 2013 6:18:08 AM INFO sun.reflect.NativeMethodAccessorImpl invoke0
with payload: {"before"=>"6333781d02b8b436717cecffdd160a887fae3bd7", "after"=>"8ff0b20a261f5d76c2fc6913ddfaee694544ab1f", "ref"=>"refs/heads/develop", "user_id"=>2, "user_name"=>"Jimmy Puckett", "repository"=>{"name"=>"<project>", "url"=>"gitlab@<git server>:<group>/<repository>.git", "description"=>"", "homepage"=>"https://<git server>/<group>/<repository>"}, "commits"=>[{"id"=>"d49b7546816e8b77b7334fce944d3341adc5a951", "message"=>"<message 1>", "timestamp"=>"2013-08-06T06:31:42-04:00", "url"=>"https://<git server>/<group>/<repository>/commit/d49b7546816e8b77b7334fce944d3341adc5a951", "author"=>{"name"=>"Jimmy Puckett", "email"=>"jimmy.puckett@spinen.com"}}, {"id"=>"8ff0b20a261f5d76c2fc6913ddfaee694544ab1f", "message"=>"<message 2>", "timestamp"=>"2013-08-06T06:34:05-04:00", "url"=>"https://<git server>/<group>/<repository>/commit/8ff0b20a261f5d76c2fc6913ddfaee694544ab1f", "author"=>{"name"=>"Jimmy Puckett", "email"=>"jimmy.puckett@spinen.com"}}], "total_commits_count"=>2}
Aug 06, 2013 6:18:08 AM INFO sun.reflect.NativeMethodAccessorImpl invoke0
project <project> matches the develop branch
Aug 06, 2013 6:18:08 AM SEVERE sun.reflect.NativeMethodAccessorImpl invoke0
Aug 06, 2013 6:18:50 AM INFO hudson.model.AsyncPeriodicWork$1 run
Started Gravatar periodic lookup
Aug 06, 2013 6:19:01 AM INFO hudson.model.AsyncPeriodicWork$1 run

I did not have the ignore hook on at that time, but I do have it on now, because I have switched to polling every x min while we are having this issue.

[elvanja]

Well, I can't find the Jenkins 1.526 upgrade, but with 1.526 all is working as expected.
Now, either you can wait until 1.526 becomes available for upgrades or you can see in regular Jenkins log if something is wrong, because it might be that Jenkins is braking somewhere, and it is not registered in the plugin/Ruby related logs.

[elvanja]

Hmm, strike that, 1.526 is available after all.
I'll upgrade and try...

[elvanja]

Yep, there was an error with non parametrized projects. I suspect this is the case at your side.
I've created a new version, you can upgrade over Jenkins or do it manually from here.
In case you have other issues, I've also added a bit more detailed logging, so it might help.
Let me know how it goes!

[yasuoza]

This worked for me. Thanks.

[elvanja]

@yasuoza thanks for the update!
@jimmypuckett has the upgrade worked for you too?

[jimmypuckett]

@elvanja, sorry for going offline on you--I wnet on vacation. Anyhow, Yes, the 2.12 does appear to have fixed the trigger. Thanks!

[elvanja]

@jimmypuckett hopefully a nice vacation :-)
Anyway, thanks for the update!