Open craigphume opened 10 years ago
FYI, same bug, also on Ubuntu 14.04 (which we just upgraded to one one of our cluster servers). Identical script / different binary works on 12.04. Had to recompile with newer opal (3.10.10)
line 13: 28400 Segmentation fault /usr/bin/timeout 40 /usr/local/bin/sipcmd -u 1980 -c XXXX -P sip -w 10.99.0.54 -x "w13000;c7071;w250;d#;w250;v$SONG;h;" -o sip.log
0:17.404 Pool:0x7f1fb2eb5700 OpalUDP Setting interface to 10.2.0.22%eth0
0:17.404 Pool:0x7f1fb2eb5700 PTLib Destroying read/write mutex 0x7f1fb2eb4900
0:17.404 Pool:0x7f1fb2eb5700 SIP INVITE transaction id=z9hG4bK8625985e-19d6-e411-9d05-0050568475a4 completing.
0:17.404 Pool:0x7f1fb2eb5700 SIP Received INVITE OK response for INVITE
0:17.404 Pool:0x7f1fb2eb5700 SIP Processing received SDP media description for audio
0:17.404 Pool:0x7f1fb2eb5700 Call IsMediaBypassPossible Call[C09626a251]-EP<sip>[6cc3915e-19d6-e411-9d05-0050568475a4] session 1
0:17.404 Pool:0x7f1fb2eb5700 OpalMan IsMediaBypassPossible: session 1
0:17.404 Pool:0x7f1fb2eb5700 OpalCon IsMediaBypassPossible: default returns false
0:17.404 Pool:0x7f1fb2eb5700 RTP Found existing RTP session 1
0:17.404 Pool:0x7f1fb2eb5700 RTP_UDP Session 1, SetRemoteSocketInfo: data channel, new=10.99.1.185:10002, local=10.2.0.22:5000-5001, remote=0.0.0.0:0-0
0:17.405 Pool:0x7f1fb2eb5700 RTP Found existing media session 1
0:17.405 Pool:0x7f1fb2eb5700 Call OpenSourceMediaStreams open for audio session 1 on Call[C09626a251]-EP<sip>[6cc3915e-19d6-e411-9d05-0050568475a4]
0:17.405 Pool:0x7f1fb2eb5700 SIP Using offered media format list
0:17.406 Pool:0x7f1fb2eb5700 Opal Initial source format from master:
Format Name = G.711-uLaw-64k
Media Type = audio
Payload Type = PCMU
Encoding Name = PCMU
Channels (R/W) = 1 UnsignedInt
Clock Rate (R/O) = 8000 UnsignedInt
Frame Time (R/O) = 8 UnsignedInt
Max Bit Rate (R/O) = 64000 UnsignedInt
Max Frame Size (R/O) = 8 UnsignedInt
Max Frames Per Packet (R/O) = 256 UnsignedInt
Needs Jitter (R/O) = 1 Boolean
Protocol (R/O) = String
Rx Frames Per Packet (R/W) = 240 UnsignedInt
Tx Frames Per Packet (R/W) = 20 UnsignedInt
Merging with capability
Format Name = G.711-uLaw-64k
Media Type = audio
Payload Type = PCMU
Encoding Name = PCMU
Channels (R/W) = 1 UnsignedInt
Clock Rate (R/O) = 8000 UnsignedInt
Frame Time (R/O) = 8 UnsignedInt
Max Bit Rate (R/O) = 64000 UnsignedInt
Max Frame Size (R/O) = 8 UnsignedInt
Max Frames Per Packet (R/O) = 256 UnsignedInt
Needs Jitter (R/O) = 1 Boolean
Protocol (R/O) = SIP String
Rx Frames Per Packet (R/W) = 240 UnsignedInt
Tx Frames Per Packet (R/W) = 20 UnsignedInt
0:17.406 Pool:0x7f1fb2eb5700 MediaFormat Merging G.711-uLaw-64k into G.711-uLaw-64k
0:17.406 Pool:0x7f1fb2eb5700 Opal Initial destination format from master:
Format Name = PCM-16
Media Type = audio
Payload Type = [pt=127]
Encoding Name =
Channels (R/W) = 1 UnsignedInt
Clock Rate (R/O) = 8000 UnsignedInt
Frame Time (R/O) = 8 UnsignedInt
Max Bit Rate (R/O) = 128000 UnsignedInt
Max Frame Size (R/O) = 16 UnsignedInt
Max Frames Per Packet (R/O) = 256 UnsignedInt
Needs Jitter (R/O) = 1 Boolean
Protocol (R/O) = String
Rx Frames Per Packet (R/W) = 240 UnsignedInt
Merging with capability
Format Name = PCM-16
Media Type = audio
Payload Type = [pt=127]
Encoding Name =
Channels (R/W) = 1 UnsignedInt
Clock Rate (R/O) = 8000 UnsignedInt
Frame Time (R/O) = 8 UnsignedInt
Max Bit Rate (R/O) = 128000 UnsignedInt
Max Frame Size (R/O) = 16 UnsignedInt
Max Frames Per Packet (R/O) = 256 UnsignedInt
Needs Jitter (R/O) = 1 Boolean
Protocol (R/O) = String
Rx Frames Per Packet (R/W) = 240 UnsignedInt
0:17.406 Pool:0x7f1fb2eb5700 MediaFormat Merging PCM-16 into PCM-16
0:17.406 Pool:0x7f1fb2eb5700 MediaFormat Merging PCM-16 into G.711-uLaw-64k
0:17.406 Pool:0x7f1fb2eb5700 MediaFormat Merging G.711-uLaw-64k into PCM-16
0:17.406 Pool:0x7f1fb2eb5700 MediaFormat Changed media option "Max Bit Rate" from "128000" to "64000"
0:17.406 Pool:0x7f1fb2eb5700 Call Selected media formats G.711-uLaw-64k -> PCM-16
0:17.406 Pool:0x7f1fb2eb5700 Call IsMediaBypassPossible Call[C09626a251]-EP<sip>[6cc3915e-19d6-e411-9d05-0050568475a4] session 1
0:17.407 Pool:0x7f1fb2eb5700 OpalMan IsMediaBypassPossible: session 1
0:17.407 Pool:0x7f1fb2eb5700 OpalCon IsMediaBypassPossible: default returns false
0:17.407 Pool:0x7f1fb2eb5700 RTP Found existing RTP session 1
0:17.407 Pool:0x7f1fb2eb5700 RTP Found existing media session 1
0:17.407 Pool:0x7f1fb2eb5700 PTLib Created read/write mutex 0x7f1f7c032020
0:17.407 Pool:0x7f1fb2eb5700 Media Created Source 0x7f1f7c031fe0
0:17.407 Pool:0x7f1fb2eb5700 Media Created RTP media session, RTP=0x1df51a0
0:17.407 Pool:0x7f1fb2eb5700 OpalMan OnOpenMediaStream Call[C09626a251]-EP<sip>[6cc3915e-19d6-e411-9d05-0050568475a4],OpalRTPMediaStream[0x7f1f7c031fe0]-Source-G.711-uLaw-64k
0:17.407 Pool:0x7f1fb2eb5700 OpalCon Opened source stream C09626a251_1 with format G.711-uLaw-64k
0:17.407 Pool:0x7f1fb2eb5700 RTP_UDP Session 1, Shutting down read.
0:17.407 Pool:0x7f1fb2eb5700 RTP_UDP Session 1 reopened for reading
0:17.407 Pool:0x7f1fb2eb5700 PTLib Created read/write mutex 0x7f1f7c032550
0:17.407 Pool:0x7f1fb2eb5700 PTLib Created read/write mutex 0x7f1f7c032970
0:17.407 Pool:0x7f1fb2eb5700 Media Created Sink 0x7f1f7c032930
0:17.407 Pool:0x7f1fb2eb5700 OpalMan OnOpenMediaStream Call[C09626a251]-EP<local>[L0262a1de2],RawMediaStream[0x7f1f7c032930]-Sink-PCM-16
0:17.407 Pool:0x7f1fb2eb5700 OpalCon Opened sink stream C09626a251_1 with format PCM-16
0:17.407 Pool:0x7f1fb2eb5700 PWLib File handle high water mark set: 31 PUDPSocket
0:17.407 Pool:0x7f1fb2eb5700 RTPEp Session 1, remote RTP address 10.99.1.185 not local.
0:17.407 Pool:0x7f1fb2eb5700 PTLib Created read/write mutex 0x7f1f7c032e40
0:17.407 Pool:0x7f1fb2eb5700 Patch Created media patch 0x7f1f7c032e00, session 1
0:17.407 Pool:0x7f1fb2eb5700 RTP_UDP Session 1, Shutting down read.
0:17.407 Pool:0x7f1fb2eb5700 Adding patch Patch[0x7f1f7c032e00] OpalRTPMediaStream[0x7f1f7c031fe0]-Source-G.711-uLaw-64k on stream OpalRTPMediaStream[0x7f1f7c031fe0]-Source-G.711-uLaw-64k
0:17.407 Pool:0x7f1fb2eb5700 RTP_UDP Session 1 reopened for reading
0:17.407 Pool:0x7f1fb2eb5700 Adding patch Patch[0x7f1f7c032e00] OpalRTPMediaStream[0x7f1f7c031fe0]-Source-G.711-uLaw-64k on stream RawMediaStream[0x7f1f7c032930]-Sink-PCM-16
0:17.407 Pool:0x7f1fb2eb5700 Patch Created Sink: format=PCM-16
0:17.407 Pool:0x7f1fb2eb5700 Patch AddSink
Source format:
Format Name = G.711-uLaw-64k
Media Type = audio
Payload Type = PCMU
Encoding Name = PCMU
Channels (R/W) = 1 UnsignedInt
Clock Rate (R/O) = 8000 UnsignedInt
Frame Time (R/O) = 8 UnsignedInt
Max Bit Rate (R/O) = 64000 UnsignedInt
Max Frame Size (R/O) = 8 UnsignedInt
Max Frames Per Packet (R/O) = 256 UnsignedInt
Needs Jitter (R/O) = 1 Boolean
Protocol (R/O) = String
Rx Frames Per Packet (R/W) = 240 UnsignedInt
Tx Frames Per Packet (R/W) = 20 UnsignedInt
Destination format:
Format Name = PCM-16
Media Type = audio
Payload Type = [pt=127]
Encoding Name =
Channels (R/W) = 1 UnsignedInt
Clock Rate (R/O) = 8000 UnsignedInt
Frame Time (R/O) = 8 UnsignedInt
Max Bit Rate (R/O) = 64000 UnsignedInt
Max Frame Size (R/O) = 16 UnsignedInt
Max Frames Per Packet (R/O) = 256 UnsignedInt
Needs Jitter (R/O) = 1 Boolean
Protocol (R/O) = String
Rx Frames Per Packet (R/W) = 240 UnsignedInt
0:17.407 Pool:0x7f1fb2eb5700 Codec G711-uLaw-64k decoder created
0:17.407 Pool:0x7f1fb2eb5700 MediaFormat Merging G.711-uLaw-64k into G.711-uLaw-64k
0:17.407 Pool:0x7f1fb2eb5700 MediaFormat Merging PCM-16 into PCM-16
0:17.407 Pool:0x7f1fb2eb5700 Patch Created primary codec G.711-uLaw-64k->PCM-16 with ID C09626a251_1
0:17.407 Pool:0x7f1fb2eb5700 Media Set data size from 16 to 3840
0:17.407 Pool:0x7f1fb2eb5700 Patch Added media stream sink RawMediaStream[0x7f1f7c032930]-Sink-PCM-16 using transcoder G.711-uLaw-64k->PCM-16, data size=3840
0:17.407 Pool:0x7f1fb2eb5700 Media RTP data size cannot be changed to 160, fixed at 2048
0:17.408 Pool:0x7f1fb2eb5700 RTPEp Session 1, remote RTP address 10.99.1.185 not local.
0:17.408 Pool:0x7f1fb2eb5700 RTP_UDP Session 1, flushed 93 RTP data packets before activating jitter buffer
0:17.408 Pool:0x7f1fb2eb5700 PTLib Created read/write mutex 0x7f1f7c0359e0
0:17.408 Pool:0x7f1fb2eb5700 Jitter Delays set to this=0x7f1f7c0359a0 packets=0 delay=20-20-1000ms
0:17.408 Pool:0x7f1fb2eb5700 Jitter Buffer created:this=0x7f1f7c0359a0 packets=0 delay=20-20-1000ms
0:17.408 Pool:0x7f1fb2eb5700 RTP Created RTP jitter buffer this=0x7f1f7c0359a0 packets=0 delay=20-20-1000ms
0:17.408 Pool:0x7f1fb2eb5700 PWLib File handle high water mark set: 32 Thread unblock pipe
0:17.408 Pool:0x7f1fb2eb5700 PTLib Created thread 0x7f1f7c0495a0 RTP Jitter
0:17.408 Pool:0x7f1fb2eb5700 PTLib Thread high water mark set: 8
0:17.408 RTP Jitter...1f98731700 PTLib Started thread 0x7f1f7c0495a0 (28410) RTP Jitter:0x7f1f98731700
0:17.408 RTP Jitter...1f98731700 Jitter Receive thread started: this=0x7f1f7c0359a0 packets=0 delay=20-20-1000ms
0:17.408 Pool:0x7f1fb2eb5700 OpalCon Sink stream of connection Call[C09626a251]-EP<local>[L0262a1de2] uses patch Patch[0x7f1f7c032e00] OpalRTPMediaStream[0x7f1f7c031fe0]-Source-G.711-uLaw-64k -> RawMediaStream[0x7f1f7c032930]-Sink-PCM-16
0:17.408 Pool:0x7f1fb2eb5700 OpalCon Source stream of connection Call[C09626a251]-EP<sip>[6cc3915e-19d6-e411-9d05-0050568475a4] uses patch Patch[0x7f1f7c032e00] OpalRTPMediaStream[0x7f1f7c031fe0]-Source-G.711-uLaw-64k -> RawMediaStream[0x7f1f7c032930]-Sink-PCM-16
0:17.408 Pool:0x7f1fb2eb5700 RTPCon Adding RFC2833 receive handler
0:17.408 Pool:0x7f1fb2eb5700 RTPCon Adding Cisco NSE receive handler
0:17.408 RTP Jitter...1f98731700 RTP Session 1, OnRxSenderReport: ssrc=1801021185 ntp=2036/3/25-20:9:18.310072 rtp=2930290688 psent=5492 osent=878720
0:17.408 RTP Jitter...1f98731700 RTP Session 1, SourceDescription item 0x7f1f80004914, current size = 13
0:17.408 Pool:0x7f1fb2eb5700 MediaFormat Merging G.711-uLaw-64k into G.711-uLaw-64k
0:17.408 RTP Jitter...1f98731700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=1801021185
item[0]: type=CNAME data="10.99.1.185"
0:17.408 Pool:0x7f1fb2eb5700 Media Media format updated on OpalRTPMediaStream[0x7f1f7c031fe0]-Source-G.711-uLaw-64k
0:17.408 RTP Jitter...1f98731700 RTP Session 1, OnExtendedReport: ssrc=1801021185
0:17.409 Pool:0x7f1fb2eb5700 MediaFormat Merging G.711-uLaw-64k into G.711-uLaw-64k
0:17.409 RTP Jitter...1f98731700 RTP Session 1, OnRxSenderReport: ssrc=1801021185 ntp=2036/3/25-20:9:18.590137 rtp=2930292928 psent=5506 osent=880960
0:17.409 RTP Jitter...1f98731700 RTP Session 1, SourceDescription item 0x7f1f80004914, current size = 13
0:17.409 RTP Jitter...1f98731700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=1801021185
item[0]: type=CNAME data="10.99.1.185"
0:17.409 RTP Jitter...1f98731700 RTP Session 1, OnExtendedReport: ssrc=1801021185
0:17.409 Pool:0x7f1fb2eb5700 MediaFormat Merging G.711-uLaw-64k into PCM-16
0:17.409 RTP Jitter...1f98731700 RTP Session 1, OnGoodbye: "" srcs=1801021185 1104544000 0 0
0:17.409 Pool:0x7f1fb2eb5700 Media Media format updated on RawMediaStream[0x7f1f7c032930]-Sink-PCM-16
0:17.409 RTP Jitter...1f98731700 RTP_UDP Session 1, Control PDU from incorrect host, is 10.2.0.22 should be 10.99.1.185
0:17.409 Pool:0x7f1fb2eb5700 Patch Updated Sink: format=G.711-uLaw-64k ok=1
0:17.409 RTP Jitter...1f98731700 RTP_UDP Session 1, Control PDU from incorrect host, is 10.2.0.22 should be 10.99.1.185
0:17.409 Pool:0x7f1fb2eb5700 PWLib File handle high water mark set: 34 Thread unblock pipe
0:17.409 Pool:0x7f1fb2eb5700 PTLib Created thread 0x7f1f7c00b2f0 Media Patch
0:17.409 Pool:0x7f1fb2eb5700 PTLib No permission to set priority level 3
0:17.409 Pool:0x7f1fb2eb5700 PTLib Thread high water mark set: 9
0:17.409 Pool:0x7f1fb2eb5700 Media Starting thread Media Patch
0:17.409 Pool:0x7f1fb2eb5700 Call GetOtherPartyConnection Call[C09626a251]-EP<sip>[6cc3915e-19d6-e411-9d05-0050568475a4]
0:17.409 Pool:0x7f1fb2eb5700 Call OpenSourceMediaStreams open for audio session 1 on Call[C09626a251]-EP<local>[L0262a1de2]
0:17.409 Pool:0x7f1fb2eb5700 SIP Using offered media format list
0:17.409 Media Patc...1f986f0700 PTLib Started thread 0x7f1f7c00b2f0 (28411) Media Patch:0x7f1f986f0700
0:17.409 Media Patc...1f986f0700 Patch Thread started for Patch[0x7f1f7c032e00] OpalRTPMediaStream[0x7f1f7c031fe0]-Source-G.711-uLaw-64k -> RawMediaStream[0x7f1f7c032930]-Sink-PCM-16
0:17.409 Media Patc...1f986f0700 PWLib File handle high water mark set: 35 PUDPSocket
0:17.409 Media Patc...1f986f0700 RTPEp Session 1, remote RTP address 10.99.1.185 not local.
0:17.409 Media Patc...1f986f0700 RTP Setting jitter buffer time from 160 to 8000
0:17.409 Media Patc...1f986f0700 Jitter Delays set to this=0x7f1f7c0359a0 packets=0 delay=20-20-1000ms
After digging through a core dump, the issue seems to be in channels.cpp:460, with a bug likely in libopal's CollectAverage. Commenting out that line seems to have solved the immediate segfault issue, and that's the end of the problem for me.
I haven't dug into the internals enough to know what the long term effects of this change are, but since our use of sipcmd is relatively simple and straightforward, I'm stopping there. FYI for others.
I am not sure if commenting out CollectAverage() is the correct thing to do. After all, it probably was there for a reason.
But admittedly, the code that invokes CollectAverage() looks extremely strange. I would suggest the following patch. At least intuitively, that looks more reasonable. But somebody more familiar with Opal and with sipcmd should probably double-check:
diff --git a/src/channels.cpp b/src/channels.cpp
index 4b8471e..bfb4810 100644
--- a/src/channels.cpp
+++ b/src/channels.cpp
@@ -430,6 +430,7 @@ bool RawMediaStream::WriteData(const BYTE *data,
PINDEX length, PINDEX &written)
{
// cout << __func__ << endl;
+ written = 0;
if (!isOpen) {
cout << "channel not open!" << endl;
return false;
@@ -449,6 +450,7 @@ bool RawMediaStream::WriteData(const BYTE *data,
if (!m_channel->Write(data, length)) {
cout << "data write failed!" << endl;
return false;
+ written = m_channel->GetLastWriteCount();
CollectAverage(data, written);
}
} else {
@@ -457,9 +459,9 @@ bool RawMediaStream::WriteData(const BYTE *data,
cout << "silence write failed!" << endl;
return false;
}
+ written = m_channel->GetLastWriteCount();
CollectAverage(silence, written);
}
- written = m_channel->GetLastWriteCount();
// cout << "wrote " << written << endl;
return true;
//return OpalRawMediaStream::WriteData(data, length, written);
Running this command will more likely crash with a segfault. $ ./sipcmd -P sip -u 1183 -c ***\ -w 192.168.20.240 -x "c1234;ws2000;d9876;w1000;h" -o ./opal.log
The opal.log has no hints for me, and the segfault will happen about 80% of the time. Using Ubuntu 14.04 x86_64