[Home]

Summary:ASTERISK-06676: [branch] chan_skinny-fixup
Reporter:Jason Parker (jparker)Labels:
Date Opened:2006-04-01 02:18:02.000-0600Date Closed:2006-07-07 15:49:06
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Channels/chan_skinny
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) skinny-debug-read.diff
( 1) tethereal.log
( 2) tethereal-2.log
( 3) tethereal-3.log
Description:chan_skinny is horribly broken, and I plan on fixing it up.

Attached is my first stab at adding many missing/broken features.  Far more will follow.

The patch currently includes debug messages and comments that don't conform to the CODING-GUIDELINES document, but that will change soon.
Comments:By: Jason Parker (jparker) 2006-04-01 02:24:53.000-0600

What seems to work:
Dialing out
Dialing in (no ringing?)
Adding softkeys
Adding lines, speeddials (number only...I got too lazy to parse out name) (speeddial=1234, can be added multiple times), etc (no hint support yet)
addons such as 7914 should work, but I've not tested them.  use "addon=7914" (can be added multiple times for multiple addons) in skinny.conf

What doesn't:
Most(all?) softkeys
line, speeddial, etc buttons
codecs besides ulaw


I've only tested this with a 7960, but I'm hoping that most others will "just work".

What I need:
button map for 7902, 7920, and 7985, possibly others
testing!  I need to know what else doesn't work.  Please be sure to give details as to which device(s) you're using.
If you can code, and you want to send in a fix/feature patch, please feel free.  As long as it's disclaimed, I'll accept just about anything (within reason).


By: sbisker (sbisker) 2006-04-03 10:36:47

Do you have a patch that will apply cleanly to 1.2.5?
By: Jason Parker (jparker) 2006-04-03 11:08:03

No, and I won't be making one either.  The changes will be far too great to maintain two copies.
By: Jason Parker (jparker) 2006-04-07 17:44:28

New patch uploaded - mostly cleanup stuff.

Converted req_alloc to use ast_calloc, and changed a bunch of memset's to use req_alloc.
By: Jason Parker (jparker) 2006-04-09 02:26:27

New patch uploaded.

Added support for a softkey or two (cfwdall and endcall).
Added better support for line button.
Added a few missing #define's (ala "RECEIVED UNKNOWN MESSAGE TYPE: 2B")

Fixed a weird size bug I was seeing on my amd64 box...


I still haven't received any test feedback on these patches...
By: sbisker (sbisker) 2006-04-10 09:49:11

Skinny(7920) -> Skinny (7920) doesn't crash, but no work.  Console messages below.

isddev01usae*CLI> skinny debug
Skinny Debugging Enabled
Received Stimulus: Line(1)
Collected digit: [7]
Collected digit: [8]
Collected digit: [3]
Collected digit: [2]
Apr 10 10:48:16 WARNING[23472]: chan_skinny.c:3323 get_input:  Skinny Client sent less data than expected.  Expected 4 but got -1.
Apr 10 10:48:16 NOTICE[23472]: chan_skinny.c:3400 skinny_session:  Skinny Session returned: Connection reset by peer
   -- Starting Skinny session from 192.168.0.156
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version RequestI>
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285@5285 (7920)
Received SoftKey Template Request
Received LineStateReq
Received SoftKeySetReq
Received Time/Date Request








Skinny(7920) -> Console/DSP  Doesn't crash, but errors below.

Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285@5285 (7920)
Received SoftKey Template Request
Received LineStateReq
Received SoftKeySetReq
Received Time/Date Request
Received Stimulus: Line(1)
Collected digit: [6]
Collected digit: [6]
Apr 10 10:37:36 WARNING[23013]: chan_skinny.c:3323 get_input:  Skinny Client sent less data than expected.  Expected 4 but got -1.
Apr 10 10:37:36 NOTICE[23013]: chan_skinny.c:3400 skinny_session:  Skinny Session returned: Connection reset by peer
   -- Starting Skinny session from 192.168.0.156
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
By: Jason Parker (jparker) 2006-04-10 20:25:32

sbisker, please try the latest patch, and let me know what it thinks the error is.  That should help a bunch.
By: sbisker (sbisker) 2006-04-11 08:14:26

Okay.  No more crash, but some total weirdness.  I attempt to call 5285 -> 7832.  Dial the number and hit send.  5285 vibrates then indicates ringing.  7832 phone rings.  I hangup 5285, but 7832 continues to ring.  I try dialing again, but 5285 show "Connected" on the screen.   I need to power off both phones to reset.  When I retry 5285 ->7832  only 5285 rings and vibrates.  Below is the console log.    

isddev01usae*CLI> skinny debug
Skinny Debugging Enabled
   -- Starting Skinny session from 192.168.0.156
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version RequestI>
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285@5285 (7920)
Received SoftKey Template Request
Received LineStateReq
Received SoftKeySetReq
Received Time/Date Request
   -- Starting Skinny session from 192.168.0.33
Device SEP0016C7988C71 is attempting to register
   -- Device '7832' successfully registered
Requesting capabilities
Version RequestI>
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 7832@7832 (7920)
Received SoftKey Template Request
Received LineStateReq
Received SoftKeySetReq
Received Time/Date Request
Received Stimulus: Line(1)
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing Macro("Skinny/5285@5285-2", "novmail|Skinny/7832@7832") in new stack
   -- Executing Set("Skinny/5285@5285-2", "TIMEOUT(absolute)=0") in new stack
   -- Channel hangup cancelled.
   -- Executing Answer("Skinny/5285@5285-2", "") in new stack
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
   -- Executing Wait("Skinny/5285@5285-2", "1") in new stack
Received Open Receive Channel Ack
ipaddr = 192.168.0.156:29102
   -- Executing Dial("Skinny/5285@5285-2", "Skinny/7832@7832||tr") in new stack
Found device: 7832
    -- skinny_request(7832@7832)
    -- Skinny cw: -1, dnd: 0, so: 0, sno: 0
skinny_new: tmp->nativeformats=12 fmt=4
    -- skinny_call(Skinny/7832@7832-1)
Displaying Prompt Status 'Ring-In'
    -- Called 7832@7832
    -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5285@5285-2
    -- Skinny/7832@7832-1 is ringing
Received Softkey Event: End Call(1)
Skinny 5285@5285 went on hook
skinny_hangup(Skinny/7832@7832-1) on 7832@7832
Clearing Display>
skinny_hangup(Skinny/5285@5285-2) on 5285@5285
Clearing Display>
Received Stimulus: Line(1)
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing Macro("Skinny/5285@5285-2", "novmail|Skinny/7832@7832") in new stack
   -- Executing Set("Skinny/5285@5285-2", "TIMEOUT(absolute)=0") in new stack
    -- Channel hangup cancelled.
    -- Executing Answer("Skinny/5285@5285-2", "") in new stack
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
   -- Executing Wait("Skinny/5285@5285-2", "1") in new stack
   -- Executing Dial("Skinny/5285@5285-2", "Skinny/7832@7832||tr") in new stack
Found device: 7832
    -- skinny_request(7832@7832)
    -- Skinny cw: -1, dnd: 0, so: 0, sno: 0
skinny_new: tmp->nativeformats=12 fmt=4
    -- skinny_call(Skinny/7832@7832-1)
Displaying Prompt Status 'Ring-In'
   -- Called 7832@7832
   -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5285@5285-2
   -- Skinny/7832@7832-1 is ringing
Received Softkey Event: End Call(1)
Skinny 5285@5285 went on hook
skinny_hangup(Skinny/7832@7832-1) on 7832@7832
Clearing Display>
skinny_hangup(Skinny/5285@5285-2) on 5285@5285
Clearing Display>
Received Stimulus: Line(1)
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
    -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing Macro("Skinny/5285@5285-2", "novmail|Skinny/7832@7832") in new stack
    -- Executing Set("Skinny/5285@5285-2", "TIMEOUT(absolute)=0") in new stack
    -- Channel hangup cancelled.
    -- Executing Answer("Skinny/5285@5285-2", "") in new stack
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
    -- Executing Wait("Skinny/5285@5285-2", "1") in new stack
   -- Executing Dial("Skinny/5285@5285-2", "Skinny/7832@7832||tr") in new stack
Found device: 7832
    -- skinny_request(7832@7832)
    -- Skinny cw: -1, dnd: 0, so: 0, sno: 0
skinny_new: tmp->nativeformats=12 fmt=4
    -- skinny_call(Skinny/7832@7832-1)
Displaying Prompt Status 'Ring-In'
    -- Called 7832@7832
    -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5285@5285-2
    -- Skinny/7832@7832-1 is ringing
Received Softkey Event: End Call(1)
Skinny 5285@5285 went on hook
skinny_hangup(Skinny/7832@7832-1) on 7832@7832
Clearing Display
skinny_hangup(Skinny/5285@5285-2) on 5285@5285
Clearing Display
Apr 11 09:07:17 WARNING[6396]: chan_skinny.c:3373 get_input:  read() returned error: Connection reset by peer
Apr 11 09:07:17 NOTICE[6396]: chan_skinny.c:3456 skinny_session:  Skinny Session returned: Connection reset by peer
Received Stimulus: Line(1)
Attempting to Clear display on Skinny 5285@5285
Clearing Display>
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing Macro("Skinny/5285@5285-2", "novmail|Skinny/7832@7832") in new stack
   -- Executing Set("Skinny/5285@5285-2", "TIMEOUT(absolute)=0") in new stack
   -- Channel hangup cancelled.
   -- Executing Answer("Skinny/5285@5285-2", "") in new stack
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
   -- Executing Wait("Skinny/5285@5285-2", "1") in new stack
   -- Executing Dial("Skinny/5285@5285-2", "Skinny/7832@7832||tr") in new stack
Found device: 7832
    -- skinny_request(7832@7832)
    -- Skinny cw: -1, dnd: 0, so: 0, sno: 0
skinny_new: tmp->nativeformats=12 fmt=4
    -- skinny_call(Skinny/7832@7832-1)
Clearing Display>
Received Softkey Event: End Call(1)
Skinny 5285@5285 went on hook
Received Open Receive Channel Ack
ipaddr = 192.168.0.156:29104
Received Open Receive Channel Ack
ipaddr = 192.168.0.156:29106
Received Open Receive Channel Ack
ipaddr = 192.168.0.156:29108
Apr 11 09:07:58 WARNING[6395]: chan_skinny.c:3373 get_input:  read() returned error: Connection reset by peer
Apr 11 09:07:58 NOTICE[6395]: chan_skinny.c:3456 skinny_session:  Skinny Session returned: Connection reset by peer
isddev01usae*CLI>

Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version RequestI>
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285@5285 (7920)
Received SoftKey Template Request
Received LineStateReq
Received SoftKeySetReq
Received Time/Date Request
Received Stimulus: Line(1)
Collected digit: [7]
Collected digit: [8]
Collected digit: [3]
Collected digit: [2]
isddev01usae*CLI> skinny debug
Skinny Debugging Enabled
Received Stimulus: Line(1)
Collected digit: [7]
Collected digit: [5]
Collected digit: [3]
Collected digit: [9]
Apr 11 09:13:50 WARNING[6445]: chan_skinny.c:3373 get_input:  read() returned error: Connection reset by peer
Apr 11 09:13:50 NOTICE[6445]: chan_skinny.c:3456 skinny_session:  Skinny Session returned: Connection reset by peer
Clearing Display>
By: sbisker (sbisker) 2006-04-11 08:24:22

Here's another backtrace from a core dump caused by chan_skinny.  Happened during the morning sometime this was based on the previous patch.

(gdb) bt
#0  0x002ad58c in memcpy () from /lib/tls/libc.so.6
#1  0x00ddd83b in req_alloc (size=Variable "size" is not available.
) at chan_skinny.c:1113
#2  0x00de11bb in skinny_new (l=0x3695e0, state=3575796) at chan_skinny.c:2374
#3  0x00368ba0 in _IO_file_jumps_mmap () from /lib/tls/libc.so.6
#4  0xb77b8268 in ?? ()
ASTERISK-1  0x002a4121 in malloc_consolidate () from /lib/tls/libc.so.6
Previous frame inner to this frame (corrupt stack?)
By: Kevin P. Fleming (kpfleming) 2006-04-11 16:40:23

Is there some reason this is sitting in here as a huge patch, and not in a developer branch or just directly committed? 120K patches are impossible to review.
By: Jason Parker (jparker) 2006-04-29 11:15:43

Developer branch added, per kpfleming's request.  The attached patches are now irrelevant.

To get the latest code, run the following command.  This branch can be updated by running `svn up` or `make update`(preferred)

svn co http://svn.digium.com/svn/asterisk/team/north/chan_skinny-fixup/ chan_skinny-fixup
By: Serge Vecher (serge-v) 2006-05-03 10:31:02

Deleted old patches and updated title to indicate where the goodies are...
By: sbisker (sbisker) 2006-05-16 14:59:23

Still no crashing, but the 7920 still doesn't work.  I've isolated all chan_skinny traffic on 1 server, and all calling goes out via IAX2 to the main server.  Regarless of calling a local skinny phone on the server, or a call out through IAX, as soon as I press the send button, the call initiates, but there is no ringing indication on the 7920, and I get the follwoing in the asterisk console.


   -- Starting Skinny session from 192.168.0.187
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285@5285 (7920)
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request

*CLI>
*CLI>
Received Stimulus: Line(1)
Setting ringer mode to '1'.
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Setting ringer mode to '1'.
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing [local:1] Dial("Skinny/5285@5285-2", "IAX2/isdpbx:password@isdpbx/7832") in new stack
   -- Called isdpbx:password@isdpbx/7832
   -- Call accepted by 192.168.1.15 (format gsm)
   -- Format for call is gsm
   -- IAX2/192.168.1.15:4569-1 answered Skinny/5285@5285-2
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
May 16 16:07:29 WARNING[13369]: chan_skinny.c:3567 get_input: read() returned error: Connection reset by peer
May 16 16:07:29 NOTICE[13369]: chan_skinny.c:3650 skinny_session: Skinny Session returned: Connection reset by peer
   -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5285@5285-2
   -- Starting Skinny session from 192.168.0.187
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285@5285 (7920)
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request
By: Jason Parker (jparker) 2006-05-16 15:45:26

I wish I had one of these to test with...  Is it possible for you to upload a tethereal dump, with a full packet log?

Something like this should do the trick.

tethereal -V -f "dst port 2000 or src port 2000" | tee tethereal.log
By: sbisker (sbisker) 2006-05-17 09:11:52

OK.  Here is the console log of:

7920 -->(Skinny)--> Asterisk -->(IAX2) --> Asterisk --> (SIP) --> 7960

The 7960 Rings, but no audio on the 7920.  Let me know if you need anything else.


Asterisk Ready.
   -- Starting Skinny session from 192.168.0.187
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285@5285 (7920)
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request

*CLI>
Received Stimulus: Line(1)
Setting ringer mode to '1'.
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Setting ringer mode to '1'.
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing [local:1] Dial("Skinny/5285@5285-2", "IAX2/isdpbx:password@isdpbx/7832") in new stack
   -- Called isdpbx:password@isdpbx/7832
   -- Call accepted by 192.168.1.15 (format gsm)
   -- Format for call is gsm
   -- IAX2/192.168.1.15:4569-1 answered Skinny/5285@5285-2
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
May 17 10:14:09 WARNING[29081]: chan_skinny.c:3567 get_input: read() returned error: Connection reset by peer
May 17 10:14:09 NOTICE[29081]: chan_skinny.c:3650 skinny_session: Skinny Session returned: Connection reset by peer
   -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5285@5285-2
   -- Starting Skinny session from 192.168.0.187
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285@5285 (7920)
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2

   -- Asked to indicate 'UNKNOWN-18' condition on channel Skinny/5285@5285-2
May 17 10:14:47 WARNING[29085]: chan_skinny.c:2361 skinny_indicate: Don't know how to indicate condition 18

   -- Hungup 'IAX2/192.168.1.15:4569-1'
 == Spawn extension (local, 7832, 1) exited non-zero on 'Skinny/5285@5285-2'
skinny_hangup(Skinny/5285@5285-2) on 5285@5285
By: Jason Parker (jparker) 2006-05-25 03:34:30

Just committed some changes.  Can you try the latest code in the branch, and see if you still get the "Connection reset by peer" error from the read()?
By: sbisker (sbisker) 2006-05-25 09:00:00

Same problem.  Ignore the app dial warnings.  I screwed up my dialplan a bit, but the behavior is the same as before.  Additionally, if I call from 7920 to 7920 via Skinny, both phoness reset.



-sb

sterisk Ready.
   -- Starting Skinny session from 192.168.0.177
Received Alarm Message: 25: Name=SEP0016C7988C77 Load=4.0(02.01) Last=CM-NAKed
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
   -- Starting Skinny session from 192.168.0.187
Received Alarm Message: 25: Name=SEP0016C7988C71 Load=4.0(02.01) Last=CM-NAKed
Device SEP0016C7988C71 is attempting to register
   -- Device '7832' successfully registered
Requesting capabilities
Version Request
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 7832
Received SoftKey Template Request
Received SoftKey Template Request
Received SoftKeySetReq
Received SoftKeySetReq
Received Time/Date Request
Received Time/Date Request

Clearing Display
Clearing Display
Received Stimulus: Line(1)
Setting ringer mode to '1'.
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Setting ringer mode to '1'.
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing [longdistance:1] Macro("Skinny/5285@5285-2", "stdexten|Skinny/7832") in new stack
   -- Executing [macro-stdexten:1] Set("Skinny/5285@5285-2", "TIMEOUT(absolute)=0") in new stack
   -- Channel hangup cancelled.
   -- Executing [macro-stdexten:2] Answer("Skinny/5285@5285-2", "") in new stack
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
   -- Executing [macro-stdexten:3] Dial("Skinny/5285@5285-2", "|20|tr") in new stack
May 25 10:00:35 WARNING[30678]: app_dial.c:811 dial_exec_full: Dial requires an argument (technology/number)
 == Spawn extension (macro-stdexten, s, 3) exited non-zero on 'Skinny/5285@5285-2' in macro 'stdexten'
 == Spawn extension (macro-stdexten, s, 3) exited non-zero on 'Skinny/5285@5285-2'
skinny_hangup(Skinny/5285@5285-2) on 5285@5285
May 25 10:00:35 WARNING[30676]: chan_skinny.c:3607 get_input: read() returned error: Connection reset by peer
May 25 10:00:35 NOTICE[30676]: chan_skinny.c:3695 skinny_session: Skinny Session returned: Connection reset by peer
   -- Starting Skinny session from 192.168.0.177
Received Alarm Message: 25: Name=SEP0016C7988C77 Load=4.0(02.01) Last=CM-NAKed
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request
Received Stimulus: Line(1)
Setting ringer mode to '1'.
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Setting ringer mode to '1'.
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing [longdistance:1] Macro("Skinny/5285@5285-2", "stdexten|Skinny/7832") in new stack
   -- Executing [macro-stdexten:1] Set("Skinny/5285@5285-2", "TIMEOUT(absolute)=0") in new stack
   -- Channel hangup cancelled.
   -- Executing [macro-stdexten:2] Answer("Skinny/5285@5285-2", "") in new stack
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
   -- Executing [macro-stdexten:3] Dial("Skinny/5285@5285-2", "|20|tr") in new stack
May 25 10:00:46 WARNING[30683]: app_dial.c:811 dial_exec_full: Dial requires an argument (technology/number)
 == Spawn extension (macro-stdexten, s, 3) exited non-zero on 'Skinny/5285@5285-2' in macro 'stdexten'
 == Spawn extension (macro-stdexten, s, 3) exited non-zero on 'Skinny/5285@5285-2'
skinny_hangup(Skinny/5285@5285-2) on 5285@5285
May 25 10:00:46 WARNING[30682]: chan_skinny.c:3607 get_input: read() returned error: Connection reset by peer
May 25 10:00:46 NOTICE[30682]: chan_skinny.c:3695 skinny_session: Skinny Session returned: Connection reset by peer
   -- Starting Skinny session from 192.168.0.177
Received Alarm Message: 25: Name=SEP0016C7988C77 Load=4.0(02.01) Last=All-CMs-Bad
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Connection to isdpbx-wireless closed.


By: Jason Parker (jparker) 2006-05-26 00:42:10

Please apply the attached patch to the latest branch, and let me know what the output looks like.  It would really help if I had a 7920 to debug this with...
By: Jason Parker (jparker) 2006-05-26 00:55:52

Also, what firmware are you using on these?  I'm not completely ready to rule out a firmware bug..
By: sbisker (sbisker) 2006-05-26 08:45:30

Here's the debug info.  If this doesn't do it, and you are in the US, contact me  sbisker@harvardgrp.com and I'll ship one of the phones to you to debug this problem once and for all.




Asterisk Ready.
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 7832
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request

*CLI>
   -- Starting Skinny session from 192.168.0.177
Received Alarm Message: 25: Name=SEP0016C7988C77 Load=4.0(02.01) Last=CM-NAKed
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request
Received Stimulus: Line(1)
Setting ringer mode to '1'.
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Setting ringer mode to '1'.
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing [longdistance:1] Macro("Skinny/5285@5285-2", "stdexten|7832|Skinny/7832@7832") in new stack
   -- Executing [macro-stdexten:1] Set("Skinny/5285@5285-2", "TIMEOUT(absolute)=0") in new stack
   -- Channel hangup cancelled.
   -- Executing [macro-stdexten:2] Answer("Skinny/5285@5285-2", "") in new stack
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
Displaying Prompt Status 'Connected'
   -- Executing [macro-stdexten:3] Dial("Skinny/5285@5285-2", "Skinny/7832@7832|20|tr") in new stack
Found device: 7832
   -- skinny_request(7832@7832)
   -- Skinny cw: 0, dnd: 0, so: 0, sno: 0
skinny_new: tmp->nativeformats=12 fmt=4
   -- skinny_call(Skinny/7832@7832-1)
Setting ringer mode to '2'.
Displaying Prompt Status 'Ring-In'
   -- Called 7832@7832
   -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5285@5285-2
   -- Skinny/7832@7832-1 is ringing
failed on read() #1 with res=-1, errno=104May 26 09:53:27 WARNING[2830]: chan_skinny.c:3609 get_input: read() returned error: Connection reset by peer
May 26 09:53:27 NOTICE[2830]: chan_skinny.c:3701 skinny_session: Skinny Session returned: Connection reset by peer
failed on read() #1 with res=-1, errno=104May 26 09:53:29 WARNING[2815]: chan_skinny.c:3609 get_input: read() returned error: Connection reset by peer
May 26 09:53:29 NOTICE[2815]: chan_skinny.c:3701 skinny_session: Skinny Session returned: Connection reset by peer
   -- Starting Skinny session from 192.168.0.177
Received Alarm Message: 25: Name=SEP0016C7988C77 Load=4.0(02.01) Last=All-CMs-Bad
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request
   -- Starting Skinny session from 192.168.0.187
Received Alarm Message: 25: Name=SEP0016C7988C71 Load=4.0(02.01) Last=All-CMs-Bad
Device SEP0016C7988C71 is attempting to register
   -- Device '7832' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 7832
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request

*CLI> stop now
Beginning asterisk shutdown....
skinny_hangup(Skinny/7832@7832-1) on 7832@7832
Setting ringer mode to '1'.
Clearing Display
 == Everyone is busy/congested at this time (1:0/0/1)
skinny_hangup(Skinny/5285@5285-2) on 5285@5285
Executing last minute cleanups
Asterisk cleanly ending (0).
By: Jason Parker (jparker) 2006-05-26 19:16:48

okay, small update was made to the branch.  Could you update, (make sure the patch I uploaded here is applied), test again, and show me cli output/tethereal log?  After looking further at your previous tethereal logs, it seems like the device is resetting itself every time it receives a tone of SKINNY_NOTONE.
By: sbisker (sbisker) 2006-05-30 08:47:37

Here's the console output.  


Asterisk Ready.
   -- Starting Skinny session from 192.168.0.151
Received Alarm Message: 25: Name=SEP0016C7988C71 Load=4.0(02.01) Last=CM-NAKed
Device SEP0016C7988C71 is attempting to register
   -- Device '7832' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 7832
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request
   -- Starting Skinny session from 192.168.0.140
Received Alarm Message: 25: Name=SEP0016C7988C77 Load=4.0(02.01) Last=CM-NAKed
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request
Received Stimulus: Line(1)
Setting ringer mode to '1'.
Attempting to Clear display on Skinny 5285@5285
Clearing Display
skinny_new: tmp->nativeformats=12 fmt=4
   -- Starting simple switch on '5285@5285'
Setting ringer mode to '1'.
Collected digit: [7]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [8]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [3]
   -- Asked to indicate 'Stop tone' condition on channel Skinny/5285@5285-2
Collected digit: [2]
   -- Executing [longdistance:1] Macro("Skinny/5285@5285-2", "stdexten|7832|Skinny/7832@7832") in new stack
   -- Executing [macro-stdexten:1] Set("Skinny/5285@5285-2", "TIMEOUT(absolute)=0") in new stack
   -- Channel hangup cancelled.
   -- Executing [macro-stdexten:2] Answer("Skinny/5285@5285-2", "") in new stack
skinny_answer(Skinny/5285@5285-2) on 5285@5285-2
I almost sent a SKINNY_NOTONE to device '5285'.  I think this causes some devices to reset.
Displaying Prompt Status 'Connected'
   -- Executing [macro-stdexten:3] Dial("Skinny/5285@5285-2", "Skinny/7832@7832|20|tr") in new stack
Found device: 7832
   -- skinny_request(7832@7832)
   -- Skinny cw: 0, dnd: 0, so: 0, sno: 0
skinny_new: tmp->nativeformats=12 fmt=4
   -- skinny_call(Skinny/7832@7832-1)
Setting ringer mode to '2'.
Displaying Prompt Status 'Ring-In'
   -- Called 7832@7832
   -- Asked to indicate 'Remote end is ringing' condition on channel Skinny/5285@5285-2
   -- Skinny/7832@7832-1 is ringing
failed on read() #1 with res=-1, errno=104May 30 09:55:56 WARNING[17808]: chan_skinny.c:3615 get_input: read() returned error: Connection reset by peer
May 30 09:55:56 NOTICE[17808]: chan_skinny.c:3707 skinny_session: Skinny Session returned: Connection reset by peer
failed on read() #1 with res=-1, errno=104May 30 09:55:56 WARNING[17807]: chan_skinny.c:3615 get_input: read() returned error: Connection reset by peer
May 30 09:55:56 NOTICE[17807]: chan_skinny.c:3707 skinny_session: Skinny Session returned: Connection reset by peer
   -- Starting Skinny session from 192.168.0.140
Received Alarm Message: 25: Name=SEP0016C7988C77 Load=4.0(02.01) Last=All-CMs-Bad
Device SEP0016C7988C77 is attempting to register
   -- Device '5285' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 5285
Received SoftKey Template Request
Received SoftKeySetReq
   -- Starting Skinny session from 192.168.0.151
Received Alarm Message: 25: Name=SEP0016C7988C71 Load=4.0(02.01) Last=All-CMs-Bad
Received Time/Date Request
Device SEP0016C7988C71 is attempting to register
   -- Device '7832' successfully registered
Requesting capabilities
Version Request
Received CapabilitiesRes
Buttontemplate requested
Adding button: 9, 1
Sending 30002 template to 7832
Received SoftKey Template Request
Received SoftKeySetReq
Received Time/Date Request

*CLI> stop now
Beginning asterisk shutdown....
skinny_hangup(Skinny/7832@7832-1) on 7832@7832
Setting ringer mode to '1'.
Clearing Display
 == Everyone is busy/congested at this time (1:0/0/1)
skinny_hangup(Skinny/5285@5285-2) on 5285@5285
Executing last minute cleanups
Asterisk cleanly ending (0).
By: Jason Parker (jparker) 2006-06-18 17:42:12

This branch has been merged to trunk.  A new branch will be created soon.

I'll keep this bug open, to keep track of things, and have one (hopefully) common place for reports.
By: Serge Vecher (serge-v) 2006-07-07 15:48:51

in trunk as of r34696. Thanks everyone for hard-work, especially qwell. Please open new bug reports if there are any issues with chan_skinny still. Thanks.