Metaswitch/sprout — pull request #882 by rkday (2014-11-23 16:40:34+00:00)
Title: Reject unparseable messages with 400 (plus some stack.cpp refactoring)

This adds some processing to reject unparseable requests with a 400 Bad Request error instead of just dropping them, as suggested in https://github.com/Metaswitch/sprout/issues/373. I've added a log for this, but not a SAS log, as I don't have a SAS to test against at present.

In order to test this well, I've refactored stack.cpp a bit:
* stack.cpp is now a bit more focused on setting up PJSIP and the right UDP/TCP transports (plus quiescing, which is quite closely tied to the transports). This continues not to be UTed (and I've deleted stack_test.cpp, which only contained one disabled test).
* thread_dispatcher.cpp handles starting the worker threads, and the small PJSIP module which clones the rdata and paasses it off to worker threads. This continues not to be UTed (because thread handling and asynchronous processing is pretty hard to UT).
* common_sip_processing.cpp handles the SIP processing that must happen on every incoming and outgoing request - logging, SAS logging, overload control, incoming request counter and (now) bad request rejection. This is UTed, although some of the SAS logging function is excluded.

I've been pretty careful about avoiding some of the ordering gotchas mentioned in the comments:
* the worker threads are still started before (and stopped after) the PJSIP threads that will pass work to them
* all the PJSIP modules are in place before the PJSIP threads that will pass work to them are started
* the PJSIP transaction layer is shut down before the other modules, as it might otherwise generate work for them

I've tested by:
* checking that the poll-sip polls get handled successfully by Sprout and Bono, including getting logged by common_sip_processing.cpp, getting passed to a worker thread, and getting handled by the options module
* hacking poll-sip to send an invalid message, and checking that Sprout and Bono both reject it with a 400 error
* shutting Sprout down and verifying that there are no crashes
* quiescing Sprout, which hits https://github.com/Metaswitch/sprout/issues/853 but doesn't seem to introduce new bugs

Logs from the acceptance and the rejection:

```
23-11-2014 14:25:27.749 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=469 (rdata0x7f8ee00919a8)
23-11-2014 14:25:27.749 UTC Verbose common_sip_processing.cpp:118: RX 339 bytes Request msg OPTIONS/cseq=469 (rdata0x7f8ee00919a8) from TCP 172.28.128.6:55758:
--start msg--

OPTIONS sip:poll-sip@172.28.128.6:5054 SIP/2.0
Via: SIP/2.0/TCP 172.28.128.6;rport;branch=z9hG4bK-469
Max-Forwards: 2
To:
From: poll-sip ;tag=469
Call-ID: poll-sip-469
CSeq: 469 OPTIONS
Contact:
Accept: application/sdp
Content-Length: 0
User-Agent: poll-sip

--end msg--
23-11-2014 14:25:27.749 UTC Debug statistic.cpp:103: Send new value for statistic incoming_requests, size 1
23-11-2014 14:25:27.749 UTC Debug zmq_lvc.cpp:167: Update to incoming_requests statistic
23-11-2014 14:25:27.749 UTC Debug zmq_lvc.cpp:250: Clearing message cache for 0x7f8f1c02a060
23-11-2014 14:25:27.749 UTC Debug thread_dispatcher.cpp:205: Queuing cloned received message 0x7f8ee0094428 for worker threads
23-11-2014 14:25:27.749 UTC Debug statistic.cpp:103: Send new value for statistic queue_size, size 5
23-11-2014 14:25:27.749 UTC Debug zmq_lvc.cpp:167: Update to queue_size statistic
23-11-2014 14:25:27.749 UTC Debug zmq_lvc.cpp:250: Clearing message cache for 0x7f8f1c0333a0
23-11-2014 14:25:27.749 UTC Debug thread_dispatcher.cpp:144: Worker thread dequeue message 0x7f8ee0094428
23-11-2014 14:25:27.749 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=469 (rdata0x7f8ee0094428)
23-11-2014 14:25:27.749 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=469 (tdta0x1ec2630) created
23-11-2014 14:25:27.749 UTC Verbose common_sip_processing.cpp:134: TX 267 bytes Response msg 200/OPTIONS/cseq=469 (tdta0x1ec2630) to TCP 172.28.128.6:55758:
--start msg--

SIP/2.0 200 OK
Via: SIP/2.0/TCP 172.28.128.6;rport=55758;received=172.28.128.6;branch=z9hG4bK-469
Call-ID: poll-sip-469
From: "poll-sip" ;tag=469
To: ;tag=z9hG4bK-469
CSeq: 469 OPTIONS
Content-Length: 0

--end msg--
23-11-2014 14:25:27.749 UTC Debug pjsip: tdta0x1ec2630 Destroying txdata Response msg 200/OPTIONS/cseq=469 (tdta0x1ec2630)
23-11-2014 14:25:27.749 UTC Debug thread_dispatcher.cpp:146: Worker thread completed processing message 0x7f8ee0094428
23-11-2014 14:25:27.749 UTC Debug thread_dispatcher.cpp:152: Request latency = 204us
23-11-2014 14:25:27.749 UTC Debug statistic.cpp:103: Send new value for statistic latency_us, size 5
23-11-2014 14:25:27.749 UTC Debug zmq_lvc.cpp:167: Update to latency_us statistic
23-11-2014 14:25:27.749 UTC Debug zmq_lvc.cpp:250: Clearing message cache for 0x7f8f1c012ff0
```

```
23-11-2014 14:27:49.826 UTC Error pjsip: sip_transport. Error processing 323 bytes packet from TCP 172.28.128.6:42036 : PJSIP syntax error exception when parsing 'Contact' header on line 8 col 10:
OPTIONS sip:poll-sip@172.28.128.6:5058 SIP/2.0
Via: SIP/2.0/TCP 172.28.128.6;rport;branch=z9hG4bK-611
Max-Forwards: 2
To:
From: poll-sip ;tag=611
Call-ID: poll-sip-611
CSeq: 611 OPTIONS
Contact: ;;
Accept: application/sdp
Content-Length: 0
User-Agent: poll-sip

-- end of packet.
23-11-2014 14:27:49.826 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=611 (rdata0x7f0d18033478)
23-11-2014 14:27:49.826 UTC Verbose common_sip_processing.cpp:118: RX 323 bytes Request msg OPTIONS/cseq=611 (rdata0x7f0d18033478) from TCP 172.28.128.6:42036:
--start msg--

OPTIONS sip:poll-sip@172.28.128.6:5058 SIP/2.0
Via: SIP/2.0/TCP 172.28.128.6;rport;branch=z9hG4bK-611
Max-Forwards: 2
To:
From: poll-sip ;tag=611
Call-ID: poll-sip-611
CSeq: 611 OPTIONS
Contact: ;;
Accept: application/sdp
Content-Length: 0
User-Agent: poll-sip

--end msg--
23-11-2014 14:27:49.826 UTC Debug statistic.cpp:103: Send new value for statistic incoming_requests, size 1
23-11-2014 14:27:49.826 UTC Debug zmq_lvc.cpp:167: Update to incoming_requests statistic
23-11-2014 14:27:49.826 UTC Debug zmq_lvc.cpp:250: Clearing message cache for 0x7f0d3002a060
23-11-2014 14:27:49.827 UTC Debug common_sip_processing.cpp:314: Report SAS start marker - trail (f)
23-11-2014 14:27:49.827 UTC Debug pjutils.cpp:1604: Logging SAS Call-ID marker, Call-ID poll-sip-611
23-11-2014 14:27:49.827 UTC Error common_sip_processing.cpp:324: Error parsing header Contact
23-11-2014 14:27:49.827 UTC Warning common_sip_processing.cpp:333: Rejecting malformed request with a 400 error
23-11-2014 14:27:49.827 UTC Debug pjsip: endpoint Response msg 400/OPTIONS/cseq=611 (tdta0x7f0d18034970) created
23-11-2014 14:27:49.827 UTC Verbose common_sip_processing.cpp:134: TX 276 bytes Response msg 400/OPTIONS/cseq=611 (tdta0x7f0d18034970) to TCP 172.28.128.6:42036:
--start msg--

SIP/2.0 400 Bad Request
Via: SIP/2.0/TCP 172.28.128.6;rport=42036;received=172.28.128.6;branch=z9hG4bK-611
Call-ID: poll-sip-611
From: "poll-sip" ;tag=611
To: ;tag=z9hG4bK-611
CSeq: 611 OPTIONS
Content-Length: 0

--end msg--
23-11-2014 14:27:49.827 UTC Debug pjsip: tdta0x7f0d1803 Destroying txdata Response msg 400/OPTIONS/cseq=611 (tdta0x7f0d18034970)
```