[Home]

Summary:ASTERISK-15423: app_jack fails to connect to jackd
Reporter:Danny (dwhitesel)Labels:
Date Opened:2010-01-13 21:07:43.000-0600Date Closed:
Priority:MajorRegression?No
Status:Open/NewComponents:Applications/app_jack
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:I have been unable to get app_jack to function as documented. I contacted Russell via email and he suggested posting here.

I have pasted what I believe to be the relevant config sections, as well as the debug output that I captured in the Additional Information field. The guidelines advise to send them as an attachment. However, I don't see a button for sending an attachment. My apologies if this is inappropriate.

I have a simple test extension configured which calls app_jack with no arguments. For debugging purposes, I added the playout of a sound after the app_jack command to verify that the dialplan was progressing past the app_jack call. It is.

Upon dialing ext 800, Asterisk attempts to connect a jack port. That connection immediately fails or is dropped, causing the dialplan to move on to the next command for that extension. Which, for debugging purposes, is playing the sound "beeperr.gsm". After that, the channel is dropped.

Some info about the test system...

Ubuntu 9.10
2.6.31-16-generic
Jack 0.116.1-4ubuntu2 (from distro repository)
Asterisk 1.6.2 (compiled from source)

Please advise if there is additional debugging output that can be of assistance. I will be happy to help any way I can.


****** ADDITIONAL INFORMATION ******

COMMAND USED TO START JACK:
/usr/bin/jackd -v -R -dalsa -dhw:0 -r48000 -p1024 -n2


--- BEGIN EXTENSIONS.CONF ---
[jack_test]
exten => _800,1,Answer()
exten => _800,2,JACK()
exten => _800,3,playback(beeperr)
--- END EXTENSIONS.CONF ---


--- BEGIN ASTERISK VERBOSE OUTPUT ---
== Using SIP RTP CoS mark 5
  -- Executing [800@default:1] Answer("SIP/501-00000005", "") in new stack
  -- Executing [800@default:2] JACK("SIP/501-00000005", "") in new stack
cannot read server event (Connection reset by peer)
zombified - calling shutdown handler
cannot send request type 2 to server
cannot read result for request type 2 from server (Broken pipe)
cannot send request type 2 to server
cannot read result for request type 2 from server (Broken pipe)
  -- Executing [800@default:3] Playback("SIP/501-00000005", "beeperr")
in new stack
  -- <SIP/501-00000005> Playing 'beeperr.gsm' (language 'en')
  -- Auto fallthrough, channel 'SIP/501-00000005' status is 'UNKNOWN'
--- END ASTERISK VERBOSE OUTPUT ---



--- BEGIN JACKD VERBOSE OUTPUT ---
load = 0.0617 max usecs: 13.000, spare = 21320.000
load = 0.0824 max usecs: 22.000, spare = 21311.000
load = 0.0810 max usecs: 17.000, spare = 21316.000
server thread back from poll
new client: SIP/501-00000004, id = 2 type 2 @ 0xb641d000 fd = 12
start poll on 4 fd's
server thread back from poll
new client SIP/501-00000004 using 13 for events
start poll on 4 fd's
server thread back from poll
registered port SIP/501-00000004:input, offset = 0
start poll on 4 fd's
server thread back from poll
registered port SIP/501-00000004:output, offset = 12288
start poll on 4 fd's
server thread back from poll
++ jack_sort_graph
++ jack_rechain_graph():
+++ client is now alsa_pcm active ? 1
client alsa_pcm: internal client, execution_order=0.
+++ client is now SIP/501-00000004 active ? 1
client SIP/501-00000004: start_fd=7, execution_order=0.
client event poll on 13 for SIP/501-00000004 starts at 1725756767356
back from client event poll after 11 usecs
subgraph starting at SIP/501-00000004 timed out (subgraph_wait_fd=9,
status = 0, state = Triggered, pollret = 0 revents = 0x0)
bad status (1) for client SIP/501-00000004 handling event (type = 8)
client SIP/501-00000004: wait_fd=9, execution_order=1 (last client).
-- jack_rechain_graph()
-- jack_sort_graph
start poll on 4 fd's
at 1725756793305 waiting on 9 for 22053 usecs, status = 1 sig =
1725756771239 awa = 1725756771264 fin = 0 dur=0
checking client alsa_pcm: awake at 0 finished at 0
checking client SIP/501-00000004: awake at 1725756771264 finished at 0
client SIP/501-00000004 has timed out
waking server thread


**** alsa_pcm: xrun of at least 0.981 msecs


server thread back from poll
trying to lock graph to remove 2 problems
we have problem clients (problems = 2
++ Removing failed clients ...
client alsa_pcm error status 0
client SIP/501-00000004 error status 10000001
removing failed client SIP/501-00000004 state = Finished errors = 10000001
removing client "SIP/501-00000004"
removing client "SIP/501-00000004" from the processing chain
+++ deactivate SIP/501-00000004
++ jack_sort_graph
++ jack_rechain_graph():
+++ client is now alsa_pcm active ? 1
client alsa_pcm: internal client, execution_order=0.
-- jack_rechain_graph()
-- jack_sort_graph
-- Removing failed clients ...
after removing clients, problems = 0
start poll on 3 fd's
load = 0.1062 max usecs: 28.000, spare = 21305.000
load = 0.0835 max usecs: 13.000, spare = 21320.000
load = 0.1097 max usecs: 29.000, spare = 21304.000
--- END JACKD VERBOSE OUTPUT ---
Comments:By: Leif Madsen (lmadsen) 2010-01-14 06:47:07.000-0600

Acknowledging issue.
By: Tilghman Lesher (tilghman) 2010-02-28 23:14:55.000-0600

Are you sending NOTICE level output to the console?  Were there any messages at this level sent while the Verbose messages were spawned to the console?
By: Clod Patry (junky) 2010-06-29 00:26:26

poke?
By: Motiejus Jakstys (motiejus) 2010-08-06 14:00:09

Try:
/usr/bin/jackd -v -R -dalsa -dhw:0 -r8000 -p1024 -n2
instead of:
/usr/bin/jackd -v -R -dalsa -dhw:0 -r48000 -p1024 -n2

because asterisk uses 8kHz everywhere...


By: David Lake (dlake02) 2011-02-05 01:08:08.000-0600

I've tried this with the latest patch to make this work, but no go:

As root:
/usr/bin/jackd -v -ddummy -r8000 -p1024 -n2

In extensions.conf:

exten => 1234,1,Answer
exten => 1234,2,JACK()

The output from the CLI is:

   -- Executing [1234@test:1] Answer("IAX2/anatoliy-833", "") in new stack
   -- Executing [1234@test:2] JACK("IAX2/anatoliy-833", "") in new stack
[Feb  5 00:51:40] ERROR[28714]: app_jack.c:414 init_jack_data: oh now did not lock output rb
[Feb  5 00:51:40] ERROR[28714]: app_jack.c:416 init_jack_data: oh now did not lock input rb
[Feb  5 00:51:45] NOTICE[28714]: app_jack.c:186 log_jack_status: Client Open Status: Failure, Server Failed
 == Spawn extension (test, 1234, 2) exited non-zero on 'IAX2/anatoliy-833'
   -- Hungup 'IAX2/anatoliy-833'

David
By: Motiejus Jakstys (motiejus) 2011-02-05 01:14:06.000-0600

Is jack server launched the same user as Asterisk?
If so, what is the output of jackd when Asterisk is trying to connect?
By: David Lake (dlake02) 2011-02-05 02:03:14.000-0600

Yes - the jackd is launched as "asterisk."  Asterisk is a member of "jackuser" and "audio" groups.

I see no incoming attempt from app_jack to the server at all.
By: David Lake (dlake02) 2011-02-05 12:18:31.000-0600

OK - if I run qjackctl as user Asterisk and then try to connect to the JACK port, I get this on the Asterisk CLI:
localhost*CLI>
   -- Accepting AUTHENTICATED call from 67.161.6.43:
      > requested format = ulaw,
      > requested prefs = (),
      > actual format = ulaw,
      > host prefs = (ulaw|alaw|gsm),
      > priority = mine
   -- Executing [1234@test:1] Answer("IAX2/anatoliy-2287", "") in new stack
   -- Executing [1234@test:2] JACK("IAX2/anatoliy-2287", "") in new stack
localhost*CLI>
Disconnected from Asterisk server

/usr/sbin/safe_asterisk: line 145:  6116 Segmentation fault      (core dumped) nice -n $PRIORITY ${ASTSBINDIR}/asterisk -f ${CLIARGS} ${ASTARGS} > /dev/${TTY} 2>&1 < /dev/${TTY}
Asterisk ended with exit status 139
Asterisk exited on signal 11.


If I run Asterisk from the command line, this is what I see:



   -- Accepting AUTHENTICATED call from 67.161.6.43:
      > requested format = ulaw,
      > requested prefs = (),
      > actual format = ulaw,
      > host prefs = (ulaw|alaw|gsm),
      > priority = mine
   -- Executing [1234@test:1] Answer("IAX2/anatoliy-1432", "") in new stack
   -- Executing [1234@test:2] JACK("IAX2/anatoliy-1432", "") in new stack
jackd 0.118.0
Copyright 2001-2009 Paul Davis, Stephane Letz, Jack O'Quinn, Torben Hohn and others.
jackd comes with ABSOLUTELY NO WARRANTY
This is free software, and you are welcome to redistribute it
under certain conditions; see the file COPYING for details


Memory locking is unlimited - this is dangerous. You should probably alter the line:
    @audio   -  memlock    unlimited
in your /etc/limits.conf to read:
    @audio   -  memlock    1556472
getting driver descriptor from /usr/local/lib/jack/jack_dummy.so
getting driver descriptor from /usr/local/lib/jack/jack_alsa.so
getting driver descriptor from /usr/local/lib/jack/jack_oss.so
getting driver descriptor from /usr/local/lib/jack/jack_net.so
JACK compiled with System V SHM support.
server `default' registered
loading driver ..
registered builtin port type 32 bit float mono audio
registered builtin port type 8 bit raw midi
clock source = system clock via clock_gettime
start poll on 3 fd's
new client: alsa_pcm, id = 1 type 1 @ 0x9eff440 fd = -1
apparent rate = 8000
creating alsa driver ... plughw:0|plughw:0|1024|2|8000|1|1|nomon|swmeter|-|32bit
control device hw:0
configuring for 8000Hz, period = 1024 frames (128.0 ms), buffer = 2 periods
ALSA: final selected sample format for capture: 32bit float little-endian
ALSA: use 2 periods for capture
ALSA: final selected sample format for playback: 32bit float little-endian
ALSA: use 2 periods for playback
new buffer size 1024
registered port system:capture_1, offset = 4096
registered port system:playback_1, offset = 0
++ jack_sort_graph
++ jack_rechain_graph():
+++ client is now alsa_pcm active ? 1
client alsa_pcm: internal client, execution_order=0.
-- jack_rechain_graph()
-- jack_sort_graph
6310 waiting for signals
server thread back from poll
new client: IAX2/anatoliy-1432, id = 2 type 2 @ 0xb680f000 fd = 27
start poll on 4 fd's
server thread back from poll
new client IAX2/anatoliy-1432 using 28 for events
start poll on 4 fd's
server thread back from poll
registered port IAX2/anatoliy-1432:input, offset = 0
start poll on 4 fd's
[Feb  5 12:03:58] NOTICE[6306]: app_jack.c:186 log_jack_status: Client Open Status: Server Started
server thread back from poll
registered port IAX2/anatoliy-1432:output, offset = 8192
start poll on 4 fd's
server thread back from poll
marking client IAX2/anatoliy-1432 with SOCKET error state = Not triggered errors = 0
trying to lock graph to remove 1 problems
we have problem clients (problems = 1
++ Removing failed clients ...
client IAX2/anatoliy-1432 error status 10000000
removing failed client IAX2/anatoliy-1432 state = Not triggered errors = 10000000
removing client "IAX2/anatoliy-1432"
removing client "IAX2/anatoliy-1432" from the processing chain
+++ deactivate IAX2/anatoliy-1432
Kill wait pid to stop
Segmentation fault
jack main caught signal 12
starting server engine shutdown
stopping driver
[root@localhost ~]#
[root@localhost ~]#
[root@localhost ~]#
[root@localhost ~]#
[root@localhost ~]#
[root@localhost ~]# lock-driven null cycle
unloading driver
freeing shared port segments
stopping server thread
stopping watchdog thread
last xrun delay: 0.000 usecs
max delay reported by backend: 13.000 usecs
freeing engine shared memory
max usecs: 0.000, engine deleted
cleaning up shared memory
cleaning up files
unregistering server `default'