Missing JOB_CREATED?

[awdrius]

Hi,

when nodejs app is under load, I start seeing 'unknown job' errors. Once one pops up, it starts cascading and is followed by more and more errors (I suspect it's because of the jobsWaiting4Created being out of sync?) until node app is restarted. I added some debug code of my own + enabled debug logging level for GearmaNode:

debug: response for client: type=JOB_CREATED, uid=10.0.1.251:4730#H:gearmand1.servername.co:2186372
[T] Submitting job with UNIQUE_ID: mwcV8bBoyuCjXq7ZPjQmFUey0OY= for authenticate_user_token
debug: packet encoded, type=SUBMIT_JOB, buffer.size=180
verbose: packet sent, type=SUBMIT_JOB, len=180
debug: job submited, name=authenticate_user_token, unique=undefined
verbose: received packet, len=138
verbose: received packet: 0 52 45 53 0 0 0 d 0 0 0 50 48 3a 67 65 61 72 6d 61 6e 64 31 2e 73 6f 63 69 61 6c 68 6f 6e 65 79 2e 63 6f 3a 32 31 38 36 33 37 32 0 7b 22 55 4e 49 51 55 45 5f 49 44 22 3a 20 22 46 39 2b 39 32 39 4f 34 42 63 42 76 46 77 35 63 79 68 57 4c 71 5a 69 69 7a 35 30 3d 22 7d 0 52 45 53 0 0 0 8 0 0 0 22 48 3a 67 65 61 72 6d 61 6e 64 31 2e 73 6f 63 69 61 6c 68 6f  6e 65 79 2e 63 6f 3a 32 31 38 36 33 37 33
verbose: packet parsed, bytes=92, type=WORK_COMPLETE
[T] Response: 10.0.1.251:4730#H:gearmand1.servername.co:2186372
debug: response for client: type=WORK_COMPLETE, uid=10.0.1.251:4730#H:gearmand1.servername.co:2186372
[2014-10-07 21:56:56,558+0000] GMD.authenticate_user_token: 94ms
[T] Submitting job with UNIQUE_ID: 6hisgIPKj5WPHTZnngLvNGvS/ZY= for authenticate_user_token
debug: packet encoded, type=SUBMIT_JOB, buffer.size=180
verbose: packet sent, type=SUBMIT_JOB, len=180
debug: job submited, name=authenticate_user_token, unique=undefined
verbose: received packet, len=46
verbose: received packet: 0 52 45 53 0 0 0 8 0 0 0 22 48 3a 67 65 61 72 6d 61 6e 64 31 2e 73 6f 63 69 61 6c 68 6f 6e 65 79 2e 63 6f 3a 32 31 38 36 33 37 34
verbose: packet parsed, bytes=46, type=JOB_CREATED
[T] job created: 10.0.1.251:4730#H:gearmand1.servername.co:2186374
[T] Response: 10.0.1.251:4730#H:gearmand1.servername.co:2186374
debug: response for client: type=JOB_CREATED, uid=10.0.1.251:4730#H:gearmand1.servername.co:2186374
verbose: received packet, len=169
verbose: received packet: 0 52 45 53 0 0 0 d 0 0 0 9d 48 3a 67 65 61 72 6d 61 6e 64 31 2e 73 6f 63 69 61 6c 68 6f 6e 65 79 2e 63 6f 3a 32 31 38 36 33 37 33 0 7b 22 75 73 65 72 6e 61 6d 65 22 3a 20 22 41 6e 6f 6e 79 6d 6f 75 73 40 34 65 62 38 34 64 63 39 2d 64 37 30 63 2d 34 66 39 35 2d 39 65 32 33 2d 62 33 33 33 31 34 38 30 63 34 65 64 22 2c 20 22 76 61 6c 69 64 22 3a 20 74 72   75 65 2c 20 22 55 4e 49 51 55 45 5f 49 44 22 3a 20 22 6d 77 63 56 38 62 42 6f 79 75 43 6a 58 71 37 5a 50 6a 51 6d 46 55 65 79 30 4f 59 3d 22 7d
verbose: packet parsed, bytes=169, type=WORK_COMPLETE
[T] Response: 10.0.1.251:4730#H:gearmand1.servername.co:2186373
[T] UNKNOWN: complete = DATA: {"username": "Anonymous@4eb84dc9-d70c-4f95-9e23-b3331480c4ed", "valid": true, "UNIQUE_ID": "mwcV8bBoyuCjXq7ZPjQmFUey0OY="}
error: unknown job, uid=10.0.1.251:4730#H:gearmand1.servername.co:2186373

You can easily spot the issue if you look for mwcV8bBoyuCjXq7ZPjQmFUey0OY= string.

Job number 2186372 is created and a new job is submitted (so I'd expect job number 2186373). There comes response for WORK_COMPLETE for the previously submitted 2186372 and it is followed by another job sumit request (which gets job number 2186374). It is then followed by response WORK_COMPLETE for job number 2186373 which is not available, but from the UNIQUE_ID I can see that it's a response to the job submitted between jobs 2186372 and 2186374.

At the moment I'm at a loss, either server did not send JOB_CREATED for that particular response or somehow data was not received/parsed or there are instances when gearmand responds with WORK_COMPLETE immediately (which would be unexpected).

I'm using gearmand 1.1.8 and GearmanNode info: GearmaNode 0.1.8, running on Node.js v0.10.32 [freebsd x64]

[veny]

hi Audrius, are you able to simulate the problem repeatedly with some piece of code or an unit test? veny

[awdrius]

Hi Veny,

I can see it fairly consistent on the production servers under load (but not that high load). I am looking into networking stack just in case but will try to put a small test script to see if I can recreate it on demand.

[awdrius]

Hey again,

so I've turned on debug level for gearmand daemon and it looks like it send JOB_CREATED OK. I think that somehow data is lost on socket/buffer or something like that. For a test period I have switched to another multi-server supporting gearman module called abraxas and so far it looks OK. I will post an update if it starts messing with data too but if there is no followup - it means that is 'just works'(tm).

P.S. I could not recreate the issue with any of my test scripts so I abandoned the idea.