[zeromq-dev] zauth failure

Sun Jan 10 17:27:04 CET 2016

See, I told you that guy with the blog knew his stuff! :-)

Yes, I should have been more specific.  Sorry.

Thanks for all you have done.

Robert

-----Original Message-----
From: pieterh at gmail.com [mailto:pieterh at gmail.com] On Behalf Of Pieter Hintjens
Sent: Saturday, January 09, 2016 11:55 PM
To: robert at layer2.com
Cc: ZeroMQ development list <zeromq-dev at lists.zeromq.org>
Subject: Re: [zeromq-dev] zauth failure

Took me a while to get that script working. :)

Next time, to help us get a grip on things faster, be explicit about the code you are testing, and how to reproduce the problem. E.g.: "I'm using CZMQ master. If I run czmq_selftest -v -t zauth in a loop, every now and then it freezes partway through".

I've run the code for a while and it doesn't crash. OK, it's a timing issue. Let's provoke that. I start a compile job in another window.
Boom! It freezes. Ctrl-C, and it restarts the test loop... another compile job, Boom! It freezes again.

So we have a simple way to reproduce.

It should not freeze. If any given step times-out, it should assert.
So let's see exactly where it's waiting. Time to insert printfs and trace it. Wow... printfs really do change behavior. Now it only freezes every five or so runs. Still, caught it, line 462:

    zstr_send (*server, "Hello, World");

Ah, looking again at the man page for ZMQ_PUSH and I wonder how this could ever work.

The server is a PUSH socket and will only accept a message if there's a peer. So I'd expect sending to block *every time* we have an authentication failure.

Hypothesis: after 'connect' and during the security handshake with the peer, for a small window, the socket accepts messages. The test case depended on this always working. If the send doesn't happen just fast enough, it'll block forever (the symptom we're seeing).

Let's check this analysis... add a 200 msec pause after zsock_connect on line 459. Now it should block every time. Bingo! We have a winner...!

Now, to fix that. Send on PUSH or DEALER is by default blocking. We could do the sleep, followed by a non-blocking send. Or, we could set a send timeout on the socket, which seems cleaner.

Which works.

Adding these two lines before the zstr_send makes the problem happen systematically, and then fixes it:

    zclock_sleep (200);
    zsock_set_sndtimeo (*server, 200);

I'll make a PR with this patch.

-Pieter

On Sun, Jan 10, 2016 at 12:59 AM, Robert Johnston <robert at layer2.com> wrote:
> Hi Pieter,
>
> Thanks for staying with me on this!
>
> OK:
>
> I built using the instructions from http://hintjens.com/blog:49 - this guy really knows his stuff ;-).
>
> And yes, they included libsodium.
>
> I wasn't running from Eclipse: I used Eclipse to try do debug it.  But it runs fine in the debugger.
>
> The attached screen shot shows it running on the command line using a bash script that runs it over and over in a while loop.  I needed the script because the failure is intermittent (remember I said "mostly works").
>
> I REALLY hate these kinds of problems.  If I enter printf statements, the problem goes away; if I try to use a debugger, the problem goes away.  It is down to deducing possible causes from a knowledge of the code.  Except I don't know much about the code!  I guess it is time to learn.  Ye Gods!!!
>
> Put the attached very sophisticated script into your czmq directory and run for a while.  You might not see it: the time, the tide, and phase of the moon will be different.
>
> Thanks for your patience.
>
> Robert
>
>
>
> -----Original Message-----
> From: pieterh at gmail.com [mailto:pieterh at gmail.com] On Behalf Of Pieter 
> Hintjens
> Sent: Friday, January 08, 2016 11:52 PM
> To: robert at layer2.com
> Cc: ZeroMQ development list <zeromq-dev at lists.zeromq.org>
> Subject: Re: [zeromq-dev] zauth failure
>
> "Running under Eclipse" :)
>
> We normally build and test from the command line. You can run the zauth test by itself using: src/czmq_selftest -v -t zauth.
>
> Which shows the same output as you're getting, except it continues with the CURVE tests (and your case seems to stop there).
>
> How exactly did you build CZMQ? Are you using libsodium?
>
> -Pieter
>
>
> On Sat, Jan 9, 2016 at 12:32 AM, Robert Johnston <robert at layer2.com> wrote:
>> I am using CZMQ.  I am curious: what seems to indicate that I am not?  Maybe I am missing something important.
>>
>> Thanks
>>
>> -----Original Message-----
>> From: pieterh at gmail.com [mailto:pieterh at gmail.com] On Behalf Of 
>> Pieter Hintjens
>> Sent: Friday, January 08, 2016 3:24 PM
>> To: robert at layer2.com
>> Cc: ZeroMQ development list <zeromq-dev at lists.zeromq.org>
>> Subject: Re: [zeromq-dev] zauth failure
>>
>> OK, I'm sorry, didn't read your first email properly.
>>
>> Are you using the jzmq zauth class? Or JeroMQ? (I thought you were using CZMQ at first).
>>
>> Authentication is failing with a 400 "no access" error code. You can debug the zap handler in zauth to see what is going on.
>>
>> -Pieter
>>
>> On Sat, Jan 9, 2016 at 12:11 AM, Robert Johnston <robert at layer2.com> wrote:
>>> The problem is happening in my application using CURVE.  I only went to the test to see what I was doing wrong.  When I found the same failure in the test it gave me a way to show you the problem.
>>>
>>> Right now, I can ignore it.  "Working mostly" allows me to keep developing.  Soon either you will fix it or I will try.
>>>
>>> Thanks for all you have done.
>>>
>>> Robert
>>>
>>> -----Original Message-----
>>> From: pieterh at gmail.com [mailto:pieterh at gmail.com] On Behalf Of 
>>> Pieter Hintjens
>>> Sent: Friday, January 08, 2016 1:49 PM
>>> To: robert at layer2.com
>>> Cc: ZeroMQ development list <zeromq-dev at lists.zeromq.org>
>>> Subject: Re: [zeromq-dev] zauth failure
>>>
>>> Sounds like a timing issue.
>>>
>>> You can simply comment out that test step, or ignore the test failure.
>>> It's not significant and we can fix it independently of you trying out the auth stuff.
>>>
>>>
>>> On Fri, Jan 8, 2016 at 9:02 PM, Robert Johnston <robert at layer2.com> wrote:
>>>> Now I am.  And still occasionally stops at same place.  Note: after 
>>>> I posted yesterday I tried to debug using Eclipse.  But the failure 
>>>> doesn't occur.  So the debugger changes something (timing?)
>>>>
>>>> -----Original Message-----
>>>> From: pieterh at gmail.com [mailto:pieterh at gmail.com] On Behalf Of 
>>>> Pieter Hintjens
>>>> Sent: Friday, January 08, 2016 11:22 AM
>>>> To: robert at layer2.com; ZeroMQ development list 
>>>> <zeromq-dev at lists.zeromq.org>
>>>> Subject: Re: [zeromq-dev] zauth failure
>>>>
>>>> Robert, are you using CZMQ and libzmq from github master?
>>>>
>>>> On Fri, Jan 8, 2016 at 12:36 AM, Robert Johnston <robert at layer2.com> wrote:
>>>>> Hi,
>>>>>
>>>>>
>>>>>
>>>>> I am adding authorization to one of our projects.  It works – mostly.
>>>>> Sometimes it freezes – quietly: no crash, assert, etc.
>>>>>
>>>>>
>>>>>
>>>>> To see what I was doing wrong I tried running your zauth_test.  It 
>>>>> works too
>>>>> - mostly. And it too sometimes freezes – quietly: no crash, assert, etc.
>>>>>
>>>>>
>>>>>
>>>>> * zauth:
>>>>>
>>>>> I: 16-01-07 15:10:46 zauth: ZAP request mechanism=NULL
>>>>> ipaddress=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:46 zauth: - allowed (NULL)
>>>>>
>>>>> I: 16-01-07 15:10:46 zauth: - ZAP reply status_code=200 
>>>>> status_text=OK
>>>>>
>>>>> I: 16-01-07 15:10:46 zauth: API command=DENY
>>>>>
>>>>> I: 16-01-07 15:10:46 zauth: - blacklisting ipaddress=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:46 zauth: ZAP request mechanism=NULL
>>>>> ipaddress=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:46 zauth: - denied (blacklist) address=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:46 zauth: - ZAP reply status_code=400 
>>>>> status_text=No access
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: API command=ALLOW
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: - whitelisting ipaddress=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: ZAP request mechanism=NULL
>>>>> ipaddress=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: - passed (whitelist) address=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: - ZAP reply status_code=200 
>>>>> status_text=OK
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: ZAP request mechanism=PLAIN
>>>>> ipaddress=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: - passed (whitelist) address=127.0.0.1
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: - denied (PLAIN) no password file 
>>>>> defined
>>>>>
>>>>> I: 16-01-07 15:10:47 zauth: - ZAP reply status_code=400 
>>>>> status_text=No access
>>>>>
>>>>>
>>>>>
>>>>> That’s all folks!!!
>>>>>
>>>>>
>>>>>
>>>>> Apparently it is waiting for Godot.
>>>>>
>>>>>
>>>>>
>>>>> As usual, any and all comments, suggestions, praise, or blame 
>>>>> gratefully accepted.
>>>>>
>>>>>
>>>>>
>>>>> Robert Johnston
>>>>>
>>>>> robert at layer2.com
>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> zeromq-dev mailing list
>>>>> zeromq-dev at lists.zeromq.org
>>>>> http://lists.zeromq.org/mailman/listinfo/zeromq-dev
>>>>>
>>>>
>>>
>>