search

Strider-CD / strider

Open Source Continuous Integration & Deployment Server
http://strider-cd.github.io/
4.59k stars 432 forks source link

Jobs don't run #977

Closed xgalen closed 7 years ago

xgalen commented 7 years ago

Hi,

After upgrading to the Strider's latest, the jobs (manual retest) don't finish the environment phase and don't do nothing else.

Node v4.4.7.

Using DEBUG=* I see this:

2016-08-04T22:09:31.048Z - error: Thu, 04 Aug 2016 22:09:31 GMT strider-github-status initing 57a3bd1a49889a0338b16d4e undefined
2016-08-04T22:09:31.053Z - error: Thu, 04 Aug 2016 22:09:31 GMT strider-github-status No github PR data undefined { __v: 0,...
Thu, 04 Aug 2016 22:09:31 GMT strider-runner-core:job Creating new job "57a3bd1a49889a0338b16d4e" for project "XXXX" using provider "github".
Thu, 04 Aug 2016 22:09:31 GMT strider-runner-core:job Running job "57a3bd1a49889a0338b16d4e"...
Thu, 04 Aug 2016 22:09:31 GMT strider-runner-core:job Job "57a3bd1a49889a0338b16d4e" runs: node { cmd: 'n 0.10',....
Thu, 04 Aug 2016 22:09:31 GMT socket.io:client ignoring packet write {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"}
Thu, 04 Aug 2016 22:09:31 GMT socket.io:client ignoring packet write {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"}
Thu, 04 Aug 2016 22:09:31 GMT socket.io:client ignoring packet write {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"}
Thu, 04 Aug 2016 22:09:31 GMT socket.io:client ignoring packet write {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"}
Thu, 04 Aug 2016 22:09:31 GMT socket.io:client ignoring packet write {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"}
Thu, 04 Aug 2016 22:09:31 GMT socket.io:client ignoring packet write {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"}
Thu, 04 Aug 2016 22:09:31 GMT socket.io:client writing packet {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"}
Thu, 04 Aug 2016 22:09:31 GMT socket.io-parser encoding packet {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"}
Thu, 04 Aug 2016 22:09:31 GMT socket.io-parser encoded {"type":2,"data":["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"],"nsp":"/"} as 2["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"]
Thu, 04 Aug 2016 22:09:31 GMT engine:socket sending packet "message" (2["job.status.command.start",["57a3bd1a49889a0338b16d4e",{"command":"n 0.10","started":"2016-08-04T22:09:31.055Z","plugin":"node","time":"2016-08-04T22:09:31.055Z"}],"yours"])
Thu, 04 Aug 2016 22:09:31 GMT mquery findOne jobs { _id: 57a3bd1a49889a0338b16d4e } { fields: undefined }
Thu, 04 Aug 2016 22:09:31 GMT engine intercepting request for path "/socket.io/"
Thu, 04 Aug 2016 22:09:31 GMT engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=LPNch9l&sid=5C2Sf3y-DfDTq3NqAAAG"
Thu, 04 Aug 2016 22:09:31 GMT engine setting new request for existing client
Thu, 04 Aug 2016 22:09:31 GMT engine:polling setting request
Thu, 04 Aug 2016 22:09:31 GMT engine:socket flushing buffer to transport
Thu, 04 Aug 2016 22:09:31 GMT engine:polling writing �42["job.new",[{"__v":0,"type":"TEST_ONLY","user_ ...
Thu, 04 Aug 2016 22:09:31 GMT engine:polling compressing
Thu, 04 Aug 2016 22:09:31 GMT engine:socket executing batch send callback
Thu, 04 Aug 2016 22:09:31 GMT engine intercepting request for path "/socket.io/"
Thu, 04 Aug 2016 22:09:31 GMT engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=LPNchCM&sid=5C2Sf3y-DfDTq3NqAAAG"
Thu, 04 Aug 2016 22:09:31 GMT engine setting new request for existing client
Thu, 04 Aug 2016 22:09:31 GMT engine:polling setting request
Thu, 04 Aug 2016 22:09:31 GMT engine:socket executing batch send callback
Thu, 04 Aug 2016 22:09:50 GMT engine intercepting request for path "/socket.io/"
Thu, 04 Aug 2016 22:09:50 GMT engine handling "POST" http request "/socket.io/?EIO=3&transport=polling&t=LPNclta&sid=5C2Sf3y-DfDTq3NqAAAG"
Thu, 04 Aug 2016 22:09:50 GMT engine setting new request for existing client
Thu, 04 Aug 2016 22:09:50 GMT engine:polling received "1:2"
Thu, 04 Aug 2016 22:09:50 GMT engine:socket packet
Thu, 04 Aug 2016 22:09:50 GMT engine:socket got ping
Thu, 04 Aug 2016 22:09:50 GMT engine:socket sending packet "pong" (undefined)
Thu, 04 Aug 2016 22:09:50 GMT engine:socket flushing buffer to transport
Thu, 04 Aug 2016 22:09:50 GMT engine:polling writing "�3"
Thu, 04 Aug 2016 22:09:50 GMT engine intercepting request for path "/socket.io/"
Thu, 04 Aug 2016 22:09:50 GMT engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=LPNclvT&sid=5C2Sf3y-DfDTq3NqAAAG"
Thu, 04 Aug 2016 22:09:50 GMT engine setting new request for existing client
Thu, 04 Aug 2016 22:09:50 GMT engine:polling setting request
Thu, 04 Aug 2016 22:09:50 GMT engine:socket executing batch send callback
Thu, 04 Aug 2016 22:10:16 GMT engine intercepting request for path "/socket.io/"
Thu, 04 Aug 2016 22:10:16 GMT engine handling "POST" http request "/socket.io/?EIO=3&transport=polling&t=LPNcsDs&sid=5C2Sf3y-DfDTq3NqAAAG"
Thu, 04 Aug 2016 22:10:16 GMT engine setting new request for existing client
Thu, 04 Aug 2016 22:10:16 GMT engine:polling received "1:2"
Thu, 04 Aug 2016 22:10:16 GMT engine:socket packet
Thu, 04 Aug 2016 22:10:16 GMT engine:socket got ping
Thu, 04 Aug 2016 22:10:16 GMT engine:socket sending packet "pong" (undefined)
Thu, 04 Aug 2016 22:10:16 GMT engine:socket flushing buffer to transport
Thu, 04 Aug 2016 22:10:16 GMT engine:polling writing "�3"
Thu, 04 Aug 2016 22:10:16 GMT engine intercepting request for path "/socket.io/"
Thu, 04 Aug 2016 22:10:16 GMT engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=LPNcsFj&sid=5C2Sf3y-DfDTq3NqAAAG"
Thu, 04 Aug 2016 22:10:16 GMT engine setting new request for existing client
Thu, 04 Aug 2016 22:10:16 GMT engine:polling setting request
Thu, 04 Aug 2016 22:10:16 GMT engine:socket executing batch send callback
Thu, 04 Aug 2016 22:10:42 GMT engine intercepting request for path "/socket.io/"
Thu, 04 Aug 2016 22:10:42 GMT engine handling "POST" http request "/socket.io/?EIO=3&transport=polling&t=LPNcya7&sid=5C2Sf3y-DfDTq3NqAAAG"
Thu, 04 Aug 2016 22:10:42 GMT engine setting new request for existing client
Thu, 04 Aug 2016 22:10:42 GMT engine:polling received "1:2"
Thu, 04 Aug 2016 22:10:42 GMT engine:socket packet
Thu, 04 Aug 2016 22:10:42 GMT engine:socket got ping
Thu, 04 Aug 2016 22:10:42 GMT engine:socket sending packet "pong" (undefined)
Thu, 04 Aug 2016 22:10:42 GMT engine:socket flushing buffer to transport
Thu, 04 Aug 2016 22:10:42 GMT engine:polling writing "�3"
Thu, 04 Aug 2016 22:10:42 GMT engine intercepting request for path "/socket.io/"
Thu, 04 Aug 2016 22:10:42 GMT engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=LPNcyby&sid=5C2Sf3y-DfDTq3NqAAAG"
Thu, 04 Aug 2016 22:10:42 GMT engine setting new request for existing client
Thu, 04 Aug 2016 22:10:42 GMT engine:polling setting request
Thu, 04 Aug 2016 22:10:42 GMT engine:socket executing batch send callback

And latest lines are repeated after some seconds but the job never ends.

The weird character "�3" appears sometimes in the log.

oliversalzburg commented 7 years ago

This is possibly an issue we recently found with a silent failure in the simple runner, related to caching,. Try clearing the cache for the project. All the debug messages that are not prefixed with strider are usually not relevant to diagnose issues.

oliversalzburg commented 7 years ago

There is an option for that in the project settings. image

xgalen commented 7 years ago

After clearing the project's cache works worse. No phase is shown, the black window remains fully black.

Now I got this errors:

2016-08-05T07:52:33.770Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent max redirects 5
2016-08-05T07:52:33.770Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent set User-Agent "StriderCD (http://stridercd.com)"
2016-08-05T07:52:33.771Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent query ref=master
2016-08-05T07:52:33.771Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent set Authorization "token 3f40a75fd7a2903c69d0150100b551ef063a6d0f"
2016-08-05T07:52:33.771Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent GET https://api.github.com/repos/mediasmart/MYREPO/contents/strider.json
2016-08-05T07:52:33.815Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent GET https://api.github.com/repos/mediasmart/MYREPO/contents/strider.json -> 404
2016-08-05T07:52:33.816Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent end GET https://api.github.com/repos/mediasmart/MYREPO/contents/strider.json
2016-08-05T07:52:33.817Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent clear timeout GET https://api.github.com/repos/mediasmart/MYREPO/contents/strider.json
Fri, 05 Aug 2016 07:52:33 GMT strider:backchannel job.prepare - strider.json not found, skipping config merge
2016-08-05T07:52:33.844Z - error: Fri, 05 Aug 2016 07:52:33 GMT superagent clear timeout GET https://api.github.com/repos/mediasmart/MYREPO/contents/strider.json

We do not use strider.json but I see also is looking for into a folder of my repo ¿?.

oliversalzburg commented 7 years ago

Yes, it's always looking for that file. Issues like this are really annoying. Strider doesn't log nearly as much as it should to make analyzing these issues possible :P

xgalen commented 7 years ago

Finally the environment phase has appeared, like before, but not more.

oliversalzburg commented 7 years ago

Sadly, @knownasilya is on vacation and I'm leaving for the weekend soon as well. The only suggestion I have left at this point is to try to run the absolutely latest development snapshots of everything. The clone and link scripts in https://github.com/oliversalzburg/strider-dev can be very helpful for that. Sorry :(

xgalen commented 7 years ago

Enjoy it @knownasilya !! Ok @oliversalzburg , enjoy your weekend too. I gonna try this, put the feedback and if does not work I will downgrade Strider until it works and continue the next week.

oliversalzburg commented 7 years ago

I can only offer a "this works for me" for the time being: We use Docker to run our tests and configure mainly through strider.json. The process is outlined at https://github.com/Strider-CD/strider/wiki/Advanced-Configuration

The Docker runner differs in many ways from the simple runner you're currently using. So it's different code (that has different problems). But maybe that approach works better for you ;)

xgalen commented 7 years ago

Finally I got Strider working with simple-runner. What I did:

I think Strider should installs the latest version of the plugins by default. I let the issue open with this suggestion and you can close if don't like it.

Anyway, I will let a chance to docker-runner coming soon. Thanks!

oliversalzburg commented 7 years ago

I bumped the versions of the two mentioned plugins.

xgalen commented 7 years ago

Thanks again.

xgalen commented 7 years ago

@oliversalzburg when installing strider in a new machine I'm having an error, I think related with this. Running npm install:

npm ERR! notarget No compatible version found: strider-simple-runner@'>=1.0.1 <2.0.0'
npm ERR! notarget Valid install targets:
npm ERR! notarget ["0.10.0","0.11.0","0.11.1","0.11.2","0.11.3","0.12.0","0.12.1","0.13.0","0.13.1","0.14.0","0.15.0","0.15.1","0.15.2","1.0.0"]

The point is before the strider's package json the simple-runner had ^1.0.0 so it had to install the 1.0.1 but didn't. On the other hand, when I updated through the UI it worked.

xgalen commented 7 years ago

The same problem with strider-custom, in this case de semver does not match though:

npm ERR! notarget No compatible version found: strider-custom@'>=1.0.0 <2.0.0'
npm ERR! notarget Valid install targets:
npm ERR! notarget ["0.1.0","0.1.1","0.1.2","0.1.3","0.2.0","0.2.1","0.3.0","0.3.1","0.4.0","0.4.1","0.5.0","0.5.1","0.5.2","0.5.3","0.5.4","0.5.5","0.6.0","0.6.1"]
oliversalzburg commented 7 years ago

The two plugins are currently only published to the "ecosystem index" (making them available as updates through the UI). The release to npm is still pending (I don't have npm publish access). I reverted the commit for now.

xgalen commented 7 years ago

I think we can close this. No problems anymore after upgranding Strider and node.