search

StefanKopieczek / gossip

SIP stack in Golang
GNU Lesser General Public License v2.1
336 stars 109 forks source link

Unable to capture responses corresponding to a request #8

Closed sushant-hiray closed 8 years ago

sushant-hiray commented 9 years ago

Here's a small test I wrote to check register messages. It is almost similar to existent test for INVITE message with some modifications

var userid string = "user1"
func TestSendRegisterUDP(t *testing.T) {
    register, err := request([]string{
        "REGISTER sip:ims.hom SIP/2.0",
        "Via: SIP/2.0/UDP " + c_CLIENT + ";rport;branch=z9hG4bK996329494",
        "Route: <sip:pcscf.ims.hom;lr>",
        "From: <sip:"+userid+"@ims.hom>;tag=1224392795",
        "To: <sip:"+userid+"@ims.hom>",
        "Call-ID: 1379275388",
        "CSeq: 1 REGISTER",
        "Contact: <sip:"+userid+"@192.168.1.39:5060>",
        "Authorization: Digest username=\""+userid+"@ims.hom\", realm=\"ims.hom\", nonce=\" \", uri=\"sip:ims.hom\", response=\" \"",
        "Max-Forwards: 70",
        "User-Agent: eXosip/3.1.0",
        "Expires: 600000",
        "Supported: path",
        "Supported: gruu",
        "Content-Length: 0",
        "",
        "",
    })
    assertNoError(t, err)
    ok, err := response([]string{
        "SIP/2.0 401 Unauthorized",
        "CSeq: 1 REGISTER",
        "Via: SIP/2.0/UDP " + c_SERVER + ";branch=z9hG4bK996329494",
        "",
        "",
    })

    test := transactionTest{actions: []action{
        &clientSend{register},
        &clientRecv{ok},
    }}
    test.Execute(t)
}

func (test *transactionTest) Execute(t *testing.T) {
    var err error
    test.client, err = NewManager("udp", c_CLIENT)
    assertNoError(t, err)
    defer test.client.Stop()

    for _, actn := range test.actions {
        testLog.Debug("Performing action %v", actn)
        actn.Act(test)
    }
}

type clientSend struct {
    msg *base.Request
}

func (actn *clientSend) Act(test *transactionTest) error {
    test.lastTx = test.client.Send(actn.msg, c_SERVER)
    return nil
}

type clientRecv struct {
    expected *base.Response
}

func (actn *clientRecv) Act(test *transactionTest) error {
    go func() error {
        for {
            fmt.Println("Checking Responses")
            responses := test.lastTx.Responses()
            select {
            case response, ok := <-responses:
                if !ok {
                    return fmt.Errorf("Response channel prematurely closed")
                } else if response.String() != actn.expected.String() {
                    return fmt.Errorf("Unexpected response:\n%s", response.String())
                } else {
                    return nil
                }
            case <-time.After(time.Duration(1)*time.Second):
                return fmt.Errorf("Timed out waiting for response")
            }
        }
    }()
    return nil
}

However, the issue here is, although I can see a response from the server via tcpdump, I'm not able to capture it via the response channel. I've couple of questions:

Note: We've a working version of Project Clearwater which acts like a server.

rynorris commented 9 years ago

It doesn't look to me like you're doing anything wrong.

If you've confirmed the response is coming into the correct IP/port then my best guess would be the transaction manager dropping it for some reason. It's very strict about what kinds of messages it will handle at the moment, and we've seen similar issues before in other interop tests.

Can you try importing the gossip/log module and running with log.SetDefaultLogLevel(log.DEBUG) at the top of your code to get debug output. If the transaction manager is dropping it, it should show up in there.

If there's nothing obvious in there, please attach the debug logs and I'll take a look.

If you find the bug and fix it, please submit a pull request. :)

sushant-hiray commented 9 years ago

Here is the debug log.

=== RUN TestAAAASetup
--- PASS: TestAAAASetup (0.00s)
=== RUN TestSendRegisterUDP
DEBUG: Chan 0x1854430c gets '0'
DEBUG: Chan 0x1854430c sends '0'
DEBUG: Parser buffer returns line 'REGISTER sip:ims.hom SIP/2.0'
DEBUG: Parser buffer returns line 'Via: SIP/2.0/UDP 192.168.1.39:5060;rport;branch=z9hG4bK996329494'
DEBUG: Parser buffer returns line 'Route: <sip:pcscf.ims.hom;lr>'
DEBUG: Parser 0x18544300 parsing header "Via: SIP/2.0/UDP 192.168.1.39:5060;rport;branch=z9hG4bK996329494"
DEBUG: Parser buffer returns line 'From: <sip:user91@ims.hom>;tag=1224392795'
DEBUG: Parser 0x18544300 parsing header "Route: <sip:pcscf.ims.hom;lr>"
DEBUG: Parser 0x18544300 has no parser for header type route
DEBUG: Parser buffer returns line 'To: <sip:user91@ims.hom>'
DEBUG: Parser 0x18544300 parsing header "From: <sip:user91@ims.hom>;tag=1224392795"
DEBUG: Parser buffer returns line 'Call-ID: 1379275388'
DEBUG: Parser 0x18544300 parsing header "To: <sip:user91@ims.hom>"
DEBUG: Parser buffer returns line 'CSeq: 1 REGISTER'
DEBUG: Parser 0x18544300 parsing header "Call-ID: 1379275388"
DEBUG: Parser buffer returns line 'Contact: <sip:user91@192.168.1.39:5060>'
DEBUG: Parser 0x18544300 parsing header "CSeq: 1 REGISTER"
DEBUG: Parser buffer returns line 'Authorization: Digest username="user91@ims.hom", realm="ims.hom", nonce=" ", uri="sip:ims.hom", response=" "'
DEBUG: Parser 0x18544300 parsing header "Contact: <sip:user91@192.168.1.39:5060>"
DEBUG: Parser buffer returns line 'Max-Forwards: 70'
DEBUG: Parser 0x18544300 parsing header "Authorization: Digest username="user91@ims.hom", realm="ims.hom", nonce=" ", uri="sip:ims.hom", response=" ""
DEBUG: Parser 0x18544300 has no parser for header type authorization
DEBUG: Parser buffer returns line 'User-Agent: eXosip/3.1.0'
DEBUG: Parser 0x18544300 parsing header "Max-Forwards: 70"
DEBUG: Parser buffer returns line 'Expires: 600000'
DEBUG: Parser 0x18544300 parsing header "User-Agent: eXosip/3.1.0"
DEBUG: Parser 0x18544300 has no parser for header type user-agent
DEBUG: Parser buffer returns line 'Supported: path'
DEBUG: Parser 0x18544300 parsing header "Expires: 600000"
DEBUG: Parser 0x18544300 has no parser for header type expires
DEBUG: Parser buffer returns line 'Supported: gruu'
DEBUG: Parser 0x18544300 parsing header "Supported: path"
DEBUG: Parser 0x18544300 has no parser for header type supported
DEBUG: Parser buffer returns line 'Content-Length: 0'
DEBUG: Parser 0x18544300 parsing header "Supported: gruu"
DEBUG: Parser 0x18544300 has no parser for header type supported
DEBUG: Parser buffer returns line ''
DEBUG: Parser 0x18544300 parsing header "Content-Length: 0"
DEBUG: Parser buffer returns chunk ''
DEBUG: Stopping parser 0x18544300
DEBUG: Parser 0x18544300 stopped
DEBUG: Parser 0x18544300 stopped
DEBUG: Chan 0x1854508c gets '0'
DEBUG: Chan 0x1854508c sends '0'
DEBUG: Parser buffer returns line 'SIP/2.0 401 Unauthorized'
DEBUG: Parser buffer returns line 'CSeq: 1 REGISTER'
DEBUG: Parser buffer returns line 'Via: SIP/2.0/UDP 192.168.1.41:5060;branch=z9hG4bK996329494'
DEBUG: Parser 0x18545080 parsing header "CSeq: 1 REGISTER"
DEBUG: Parser buffer returns line ''
DEBUG: Parser 0x18545080 parsing header "Via: SIP/2.0/UDP 192.168.1.41:5060;branch=z9hG4bK996329494"
DEBUG: Parser buffer returns chunk ''
DEBUG: Chan 0x1854430c will dispose
DEBUG: Chan 0x1854430c disposing...
DEBUG: Chan 0x1854430c disposed
DEBUG: Stopping parser 0x18545080
DEBUG: Parser 0x18545080 stopped
DEBUG: Notifier 0x18537100 has new listener 0x185455c0
DEBUG: Notifier 0x18537260 has new listener 0x18545780
>>> DEBUG: Performing action &{0x18544480}
DEBUG: Sending to 192.168.1.41:5060: REGISTER sip:ims.hom SIP/2.0
Via: SIP/2.0/UDP 192.168.1.39:5060;rport;branch=z9hG4bK996329494
route: <sip:pcscf.ims.hom;lr>
From: <sip:user91@ims.hom>;tag=1224392795
To: <sip:user91@ims.hom>
Call-Id: 1379275388
CSeq: 1 REGISTER
Contact: <sip:user91@192.168.1.39:5060>
authorization: Digest username="user91@ims.hom", realm="ims.hom", nonce=" ", uri="sip:ims.hom", response=" "
Max-Forwards: 70
user-agent: eXosip/3.1.0
expires: 600000
supported: path
supported: gruu
Content-Length: 0

DEBUG: Sending message REGISTER sip:ims.hom SIP/2.0 (CSeq: CSeq: 1 REGISTER) to 192.168.1.41:5060
>>> DEBUG: Performing action &{0x18538780}
DEBUG: Parser 0x18545080 stopped
DEBUG: [transaction] : fetching the responses channel
--- PASS: TestSendRegisterUDP (0.00s)
=== RUN TestResendInviteOK
INFO: Begin listening for UDP on address 192.168.1.39:5060
INFO: Stopped listening for UDP on %!!(MISSING)s(func() net.Addr=0x8118930)
DEBUG: Chan 0x1854508c will dispose
DEBUG: Chan 0x1854508c disposing...
DEBUG: Chan 0x1854508c disposed
--- PASS: TestResendInviteOK (0.00s)
PASS
ok      github.com/stefankopieczek/gossip/transaction   0.005s

So, although the responses := test.lastTx.Responses() is being called, there are no responses fetched from there, and hence it gets timedout.

Also I'm not sure if this is worth mentioning:

20:03:49.843493 IP 192.168.1.39.48318 > bono-1.sip: SIP, length: 502
20:03:49.860577 IP bono-1.sip > 192.168.1.39.48318: SIP, length: 426

These are the packet summaries. So the client binds at port 48318 and server responds back at port 48318. I'm not sure if the transaction is actually searching for responses on that port. Ideally it should. The detailed tcpdump log can be found here You might need to use wireshark to open it though. Either ways, the above summary should suit the purpose.

I'm not able to spot any bug in the log, but if you can help me spotting I'll ship in a fix.

rynorris commented 9 years ago

Ok, so looks like we don't currently support the "rport" parameter in the Via header.

We haven't looked very hard at the various extension RFCs (rport defined in RFC 3581), so haven't got around to implementing this yet.

If your client isn't behind a NAT, then removing the rport parameter should cause your server to send the response to the port in the Via header, and then you should get it.

If removing rport isn't an option, then you could try using TCP instead? That would avoid this problem entirely.

sushant-hiray commented 9 years ago

Thanks @DiscoViking for the suggestion. I could remove the rport parameter. I'm yet to tap on the response though. I tried a couple of variations of the test.

First

Similar to what I posted earlier, removing the rport parameter.

Here is the log:

=== RUN TestAAAASetup
--- PASS: TestAAAASetup (0.00s)
=== RUN TestSendRegisterUDP
DEBUG: Chan 0x1854428c gets '0'
DEBUG: Chan 0x1854428c sends '0'
DEBUG: Parser buffer returns line 'REGISTER sip:ims.hom SIP/2.0'
DEBUG: Parser buffer returns line 'Via: SIP/2.0/UDP 192.168.1.39:5060;branch=z9hG4bK996329494'
DEBUG: Parser buffer returns line 'Route: <sip:pcscf.ims.hom;lr>'
DEBUG: Parser 0x18544280 parsing header "Via: SIP/2.0/UDP 192.168.1.39:5060;branch=z9hG4bK996329494"
DEBUG: Parser buffer returns line 'From: <sip:user91@ims.hom>;tag=1224392795'
DEBUG: Parser 0x18544280 parsing header "Route: <sip:pcscf.ims.hom;lr>"
DEBUG: Parser 0x18544280 has no parser for header type route
DEBUG: Parser buffer returns line 'To: <sip:user91@ims.hom>'
DEBUG: Parser 0x18544280 parsing header "From: <sip:user91@ims.hom>;tag=1224392795"
DEBUG: Parser buffer returns line 'Call-ID: 1379275388'
DEBUG: Parser 0x18544280 parsing header "To: <sip:user91@ims.hom>"
DEBUG: Parser buffer returns line 'CSeq: 1 REGISTER'
DEBUG: Parser 0x18544280 parsing header "Call-ID: 1379275388"
DEBUG: Parser buffer returns line 'Contact: <sip:user91@192.168.1.39:5060>'
DEBUG: Parser 0x18544280 parsing header "CSeq: 1 REGISTER"
DEBUG: Parser buffer returns line 'Authorization: Digest username="user91@ims.hom", realm="ims.hom", nonce=" ", uri="sip:ims.hom", response=" "'
DEBUG: Parser 0x18544280 parsing header "Contact: <sip:user91@192.168.1.39:5060>"
DEBUG: Parser buffer returns line 'Max-Forwards: 70'
DEBUG: Parser 0x18544280 parsing header "Authorization: Digest username="user91@ims.hom", realm="ims.hom", nonce=" ", uri="sip:ims.hom", response=" ""
DEBUG: Parser 0x18544280 has no parser for header type authorization
DEBUG: Parser buffer returns line 'User-Agent: eXosip/3.1.0'
DEBUG: Parser 0x18544280 parsing header "Max-Forwards: 70"
DEBUG: Parser buffer returns line 'Expires: 600000'
DEBUG: Parser 0x18544280 parsing header "User-Agent: eXosip/3.1.0"
DEBUG: Parser 0x18544280 has no parser for header type user-agent
DEBUG: Parser buffer returns line 'Supported: path'
DEBUG: Parser 0x18544280 parsing header "Expires: 600000"
DEBUG: Parser 0x18544280 has no parser for header type expires
DEBUG: Parser buffer returns line 'Supported: gruu'
DEBUG: Parser 0x18544280 parsing header "Supported: path"
DEBUG: Parser 0x18544280 has no parser for header type supported
DEBUG: Parser buffer returns line 'Content-Length: 0'
DEBUG: Parser 0x18544280 parsing header "Supported: gruu"
DEBUG: Parser 0x18544280 has no parser for header type supported
DEBUG: Parser buffer returns line ''
DEBUG: Parser 0x18544280 parsing header "Content-Length: 0"
DEBUG: Parser buffer returns chunk ''
DEBUG: Stopping parser 0x18544280
DEBUG: Parser 0x18544280 stopped
DEBUG: Parser 0x18544280 stopped
DEBUG: Chan 0x1854508c gets '0'
DEBUG: Chan 0x1854508c sends '0'
DEBUG: Parser buffer returns line 'SIP/2.0 401 Unauthorized'
DEBUG: Parser buffer returns line 'CSeq: 1 REGISTER'
DEBUG: Parser buffer returns line 'Via: SIP/2.0/UDP 192.168.1.41:5060;branch=z9hG4bK996329494'
DEBUG: Parser 0x18545080 parsing header "CSeq: 1 REGISTER"
DEBUG: Parser buffer returns line ''
DEBUG: Parser 0x18545080 parsing header "Via: SIP/2.0/UDP 192.168.1.41:5060;branch=z9hG4bK996329494"
DEBUG: Parser buffer returns chunk ''
DEBUG: Chan 0x1854428c will dispose
DEBUG: Chan 0x1854428c disposing...
DEBUG: Chan 0x1854428c disposed
DEBUG: Stopping parser 0x18545080
DEBUG: Parser 0x18545080 stopped
Now proceeding further
DEBUG: Notifier 0x18537100 has new listener 0x185455c0
DEBUG: Notifier 0x18537260 has new listener 0x18545780
>>> DEBUG: Performing action &{0x18544400}
DEBUG: [manager::Send]Sending to 192.168.1.41:5060: REGISTER sip:ims.hom SIP/2.0
Via: SIP/2.0/UDP 192.168.1.39:5060;branch=z9hG4bK996329494
route: <sip:pcscf.ims.hom;lr>
From: <sip:user91@ims.hom>;tag=1224392795
To: <sip:user91@ims.hom>
Call-Id: 1379275388
CSeq: 1 REGISTER
Contact: <sip:user91@192.168.1.39:5060>
authorization: Digest username="user91@ims.hom", realm="ims.hom", nonce=" ", uri="sip:ims.hom", response=" "
Max-Forwards: 70
user-agent: eXosip/3.1.0
expires: 600000
supported: path
supported: gruu
Content-Length: 0

REGISTER FSM created
DEBUG: Sending message REGISTER sip:ims.hom SIP/2.0 (CSeq: CSeq: 1 REGISTER) to 192.168.1.41:5060
>>> DEBUG: Performing action &{0x185387b0}
DEBUG: Parser 0x18545080 stopped
Checking Responses
DEBUG: [transaction] : fetching the responses channel
--- PASS: TestSendRegisterUDP (0.01s)
PASS
ok      github.com/stefankopieczek/gossip/transaction   0.009s

Also, removing rport was successful, now the server replied back on sip port. Here is the packet summary:

09:06:32.529855 IP 192.168.1.39.60806 > bono-1.sip: SIP, length: 496
09:06:32.548625 IP bono-1.sip > 192.168.1.39.sip: SIP, length: 414

As you can notice, this time the server replied back on the port 5060.

Second

However, I felt not a lot of things happened in the second Action, which is the client receive one. So I wondered if there is any issue with the way I wrote the corresponding function. So instead of it being a go routine like the one I posted on the first comment, I removed the go-routine part.

func (actn *clientRecv) Act(test *transactionTest) error {
    //go func() error {
        for {
            fmt.Println("Checking Responses")
            responses := test.lastTx.Responses()
            select {
            case response, ok := <-responses:
                if !ok {
                    return fmt.Errorf("Response channel prematurely closed")
                } else if response.String() != actn.expected.String() {
                    return fmt.Errorf("Unexpected response:\n%s", response.String())
                } else {
                    return nil
                }
            case <-time.After(time.Duration(1)*time.Second):
                return fmt.Errorf("Timed out waiting for response")
            }
        }
//    }()
    return nil
}

And then I traced the log again, I'll just post the new additions as rest of the log was same.

>>> DEBUG: Performing action &{0x18526780}
Checking Responses
DEBUG: [transaction] : fetching the responses channel
DEBUG: Parser 0x18545080 stopped
INFO: Begin listening for UDP on address 192.168.1.39:5060
DEBUG: Chan 0x1854508c will dispose
DEBUG: Chan 0x1854508c disposing...
DEBUG: Chan 0x1854508c disposed
INFO: Stopped listening for UDP on %!!(MISSING)s(func() net.Addr=0x81191f0)
--- PASS: TestSendRegisterUDP (1.00s)

So in this case, it tried to listen for UDP requests, however, it stopped listening immediately I suppose, so that is perhaps the bug (not sure). And that also brings me to one more query, whether we should try to listen in a new go routine or not?

rynorris commented 9 years ago

Apologies for the extremely late response. I was away on holiday for the whole of May, and have only just had time to get back to this.

Two things:

1 - Your Act functions can't do its listening in a goroutine. If it does, then it returns immediately and the test will exit. This is what you saw the first time.

2 - I'm not 100% on what happened the second time, but you should be checking the return code of your Act function, otherwise the test will never fail!

Change

actn.Act(test)

to

if err := actn.Act(test); err != nil {
    t.Fatal(err)
}

Then you should get the relevant error message from your action printed.

Conclusion

Given that your test ran for exactly 1.00s, I would guess it's a timeout. Meaning your test just never received the response. (Also the debug logs would show if a message was being parsed).

It looks to me like the test just all happened so fast the transport layer hadn't properly initialized by the time the response came in!

Note we don't get the line

INFO: Begin listening for UDP on address 192.168.1.39:5060

Until well after the "clientResp" action has started, which means it's entirely possible the response has already arrived and been ditched by the OS because we weren't listening.

Try putting in a small sleep before starting you actions and see if that fixes it.

ie:

time.Sleep(100 * time.Millisecond)
for _, actn := range test.actions {
    testLog.Debug("Performing action %v", actn)
    actn.Act(test)
}
StefanKopieczek commented 8 years ago

Propose we close this as WAD; I think your analysis is right here on the absence of evidence to the contrary.

rynorris commented 8 years ago

Agree.