ASTERISK-19081: Call files in /var/spool/asterisk/outgoing are sometime not read and processed by pbx

[Home]

Summary: ASTERISK-19081: Call files in /var/spool/asterisk/outgoing are sometime not read and processed by pbx_spool.c

Reporter: Knut Bakke (knutbakke) Labels:

Date Opened: 2011-12-20 01:42:43.000-0600 Date Closed: 2012-02-13 16:06:35.000-0600

Priority: Major Regression?

Status: Closed/Complete Components: PBX/pbx_spool

Versions: Frequency of
Occurrence Frequent

Related
Issues:

Environment: Attachments: ( 0) jira_asterisk_19081_v1.6.2.patch

Description: The call file 11223344 is written to spool dir at 11:02:59, but not processed by pbx_spool.c until 11:03:15,
giving a 15 sec delay before placing the call.

A workaround has been put into the "callfile generator", touching /var/spool/asterisk/outgoing 1.5 sec after writing the file to the directory.

In function scan_thread, pbx_spool.c is not detecting new files written to spool/outgoing.

pbx_spool.c har been instrumented to give more printouts with the fault apprears, instrumented scan_thread function enclosed.
The corresponding asterisk log is enclosed at the end.

/* INSTRUMENTED CODE TO GIVE MORE PRINTOUTS IN AST LOG */
{code}
static void *scan_thread(void *unused)
{
struct stat st;
DIR *dir;
struct dirent *de;
char fn[256];
int res;
time_t last = 0, next = 0, now;
struct timespec ts = { .tv_sec = 1 };

while (!ast_fully_booted) {
nanosleep(&ts, NULL);
}

for(;;) {
/* Wait a sec */
nanosleep(&ts, NULL);
time(&now);

if (stat(qdir, &st)) {
ast_log(LOG_WARNING, "Unable to stat %s\n", qdir);
continue;
}

/* Make sure it is time for us to execute our check */
if ((st.st_mtime == last) && (next && (next > now))) {
ast_log(LOG_DEBUG, "Check is not executed. next: %ld, mtime: %ld, now: %ld\n", next, st.st_mtime, now);
continue;
}

#if 0
printf("atime: %ld, mtime: %ld, ctime: %ld\n", st.st_atime, st.st_mtime, st.st_ctime);
printf("Ooh, something changed / timeout\n");
#endif
next = 0;
last = st.st_mtime;

if (!(dir = opendir(qdir))) {
ast_log(LOG_WARNING, "Unable to open directory %s: %s\n", qdir, strerror(errno));
continue;
}

while ((de = readdir(dir))) {
snprintf(fn, sizeof(fn), "%s/%s", qdir, de->d_name);
if (stat(fn, &st)) {
ast_log(LOG_WARNING, "Unable to stat %s: %s\n", fn, strerror(errno));
continue;
}
if (!S_ISREG(st.st_mode))
continue;

if (st.st_mtime <= now) {
res = scan_service(fn, now, st.st_atime);
if (res > 0) {
/* Update next service time */
if (!next || (res < next)) {
next = res;
}
} else if (res) {
ast_log(LOG_WARNING, "Failed to scan service '%s'\n", fn);
} else if (!next) {
/* Expired entry: must recheck on the next go-around */
next = st.st_mtime;
}
} else {
ast_log(LOG_DEBUG, "Timestamp disqualified %s next: %ld, mtime: %ld, now: %ld\n", fn, next, st.st_mtime, now);
/* Update "next" update if necessary */
if (!next || (st.st_mtime < next))
next = st.st_mtime;
}
}
closedir(dir);
}
return NULL;
}
{code}

*****************
Here is the ast log with the printout., search for COMMENT. Follow phoneno 11223344.
{noformat}
[Dec 16 11:02:50] WARNING[9667] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:02:50] WARNING[9667] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:02:50] VERBOSE[9667] app_dial.c: -- Called phonect/41542617
[Dec 16 11:02:51] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030070, mtime: 1324029769, now: 1324029771
[Dec 16 11:02:52] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030070, mtime: 1324029769, now: 1324029772
[Dec 16 11:02:53] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030070, mtime: 1324029769, now: 1324029773
[Dec 16 11:02:53] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available
[Dec 16 11:02:53] VERBOSE[9667] app_dial.c: -- SIP/phonect-00000e77 is making progress passing it to Local/12345678@outgoing_pd-0661;2
[Dec 16 11:02:54] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030070, mtime: 1324029769, now: 1324029774
[Dec 16 11:02:55] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030070, mtime: 1324029769, now: 1324029775
[Dec 16 11:02:56] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030070, mtime: 1324029769, now: 1324029776
[Dec 16 11:02:56] VERBOSE[8972] pbx.c: -- Executing [h@macro-local-pd-agent:1] AGI("SIP/phonect-00000e5e", "controllerChannel,11300 hangup:40001094") in new stack
[Dec 16 11:02:56] VERBOSE[8972] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/controllerChannel
[Dec 16 11:02:56] VERBOSE[8972] res_agi.c: -- <SIP/phonect-00000e5e>AGI Script controllerChannel completed, returning 0
[Dec 16 11:02:56] VERBOSE[8972] pbx.c: -- Executing [h@macro-local-pd-agent:2] Hangup("SIP/phonect-00000e5e", "") in new stack
[Dec 16 11:02:56] VERBOSE[8972] features.c: == Spawn extension (macro-local-pd-agent, h, 2) exited non-zero on 'SIP/phonect-00000e5e'
[Dec 16 11:02:56] VERBOSE[8972] app_macro.c: == Spawn extension (macro-local-pd-agent, s, 2) exited non-zero on 'SIP/phonect-00000e5e' in macro 'local-pd-agent'
[Dec 16 11:02:56] VERBOSE[8972] pbx.c: == Spawn extension (outgoing_pd, s, 103) exited non-zero on 'SIP/phonect-00000e5e'
[Dec 16 11:02:56] VERBOSE[8989] app_mixmonitor.c: == MixMonitor close filestream
[Dec 16 11:02:56] NOTICE[8972] pbx_spool.c: Call completed to local/40001094@outgoing_pd
[Dec 16 11:02:56] VERBOSE[8989] app_mixmonitor.c: == Executing [lame --preset voice -v -B 64 -a /var/tmg/record/dump/tmgpd/rec_40001094_16122011_110144_1324029701208668.wav && rm -f /var/tmg/record/dump/tmgpd/rec_40001094_16122011_110144_1324029701208668.wav]
[Dec 16 11:02:57] VERBOSE[8989] app_mixmonitor.c: == End MixMonitor Recording Local/40001094@outgoing_pd-b5cc;1
[Dec 16 11:02:57] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99351111 next: 0, mtime: 1324030355, now: 1324029777
[Dec 16 11:02:57] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 1324030355, mtime: 1324030320, now: 1324029777
[Dec 16 11:02:57] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99631440 next: 1324030320, mtime: 1324030244, now: 1324029777
[Dec 16 11:02:57] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/91529685 next: 1324030244, mtime: 1324030337, now: 1324029777
[Dec 16 11:02:57] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99645668 next: 1324030244, mtime: 1324030280, now: 1324029777
[Dec 16 11:02:57] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99731742 next: 1324030244, mtime: 1324030319, now: 1324029777
[Dec 16 11:02:57] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99737345 next: 1324030244, mtime: 1324030364, now: 1324029777
[Dec 16 11:02:57] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/12345678 next: 1324030244, mtime: 1324030370, now: 1324029777
[Dec 16 11:02:58] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029776, now: 1324029778
[Dec 16 11:02:58] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available
[Dec 16 11:02:59] WARNING[6343] chan_sip.c: Received response: "Forbidden" from '"Name" <sip:61606744@213.167.121.90>;tag=as63d8fbc0'

COMMENT: 11223344 is now written to spool dir at 11:02:59, msec not known. This info is based on other logs.
pbx_spool.c does not detect it until 11:03:14. Giving a 15 sec delay before placing the call.

[Dec 16 11:02:59] VERBOSE[9638] app_dial.c: -- SIP/phonect-00000e75 is circuit-busy
[Dec 16 11:02:59] VERBOSE[9638] app_dial.c: == Everyone is busy/congested at this time (1:0/1/0)
[Dec 16 11:02:59] VERBOSE[9638] pbx.c: -- Executing [99351111@outgoing_pd:3] Goto("Local/99351111@outgoing_pd-de2b;2", "s-CONGESTION,1") in new stack
[Dec 16 11:02:59] VERBOSE[9638] pbx.c: -- Goto (outgoing_pd,s-CONGESTION,1)
[Dec 16 11:02:59] VERBOSE[9638] pbx.c: -- Executing [s-CONGESTION@outgoing_pd:1] NoOp("Local/99351111@outgoing_pd-de2b;2", "CONGESTION DIALSTATUS=CONGESTION Hangupcause=21") in new stack
[Dec 16 11:02:59] VERBOSE[9638] pbx.c: -- Executing [s-CONGESTION@outgoing_pd:2] AGI("Local/99351111@outgoing_pd-de2b;2", "controllerChannel,11300 termination:99351111:dialStatus:CONGESTION:hangupCause:=21") in new stack
[Dec 16 11:02:59] VERBOSE[9638] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/controllerChannel
[Dec 16 11:02:59] VERBOSE[9638] res_agi.c: -- <Local/99351111@outgoing_pd-de2b;2>AGI Script controllerChannel completed, returning 0
[Dec 16 11:02:59] VERBOSE[9638] pbx.c: -- Executing [s-CONGESTION@outgoing_pd:3] Hangup("Local/99351111@outgoing_pd-de2b;2", "") in new stack
[Dec 16 11:02:59] VERBOSE[9638] pbx.c: == Spawn extension (outgoing_pd, s-CONGESTION, 3) exited non-zero on 'Local/99351111@outgoing_pd-de2b;2'
[Dec 16 11:02:59] VERBOSE[9637] pbx.c: -- Executing [failed@outgoing_pd:1] NoOp("OutgoingSpoolFailed", "======== CALLFILE FAILED to 99351111 failed 1") in new stack
[Dec 16 11:02:59] VERBOSE[9637] pbx.c: -- Auto fallthrough, channel 'OutgoingSpoolFailed' status is 'UNKNOWN'
[Dec 16 11:02:59] NOTICE[9637] pbx_spool.c: Call failed to go through, reason (1) Hangup
[Dec 16 11:02:59] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 0, mtime: 1324030320, now: 1324029779
[Dec 16 11:02:59] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99631440 next: 1324030320, mtime: 1324030244, now: 1324029779
[Dec 16 11:02:59] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/91529685 next: 1324030244, mtime: 1324030337, now: 1324029779
[Dec 16 11:02:59] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99645668 next: 1324030244, mtime: 1324030280, now: 1324029779
[Dec 16 11:02:59] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99731742 next: 1324030244, mtime: 1324030319, now: 1324029779
[Dec 16 11:02:59] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99737345 next: 1324030244, mtime: 1324030364, now: 1324029779
[Dec 16 11:02:59] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/12345678 next: 1324030244, mtime: 1324030370, now: 1324029779
[Dec 16 11:03:00] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029780
[Dec 16 11:03:01] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029781
[Dec 16 11:03:02] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029782
[Dec 16 11:03:03] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029783
[Dec 16 11:03:04] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:04] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029784
[Dec 16 11:03:05] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029785
[Dec 16 11:03:06] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029786
[Dec 16 11:03:07] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029787
[Dec 16 11:03:08] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029788
[Dec 16 11:03:09] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:09] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029789
[Dec 16 11:03:10] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029790
[Dec 16 11:03:10] VERBOSE[9658] app_dial.c: -- SIP/phonect-00000e76 answered Local/99737345@outgoing_pd-f327;2
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@outgoing_pd:100] NoOp("Local/99737345@outgoing_pd-f327;1", "DIALSTATUS=") in new stack
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@outgoing_pd:101] AGI("Local/99737345@outgoing_pd-f327;1", "controllerChannel,11300 answer:99737345:timestamp:20111216120310.000") in new stack
[Dec 16 11:03:10] VERBOSE[9657] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/controllerChannel
[Dec 16 11:03:10] ERROR[9657] utils.c: write() returned error: Broken pipe
[Dec 16 11:03:10] ERROR[9657] utils.c: write() returned error: Broken pipe
[Dec 16 11:03:10] VERBOSE[9657] res_agi.c: -- <Local/99737345@outgoing_pd-f327;1>AGI Script controllerChannel completed, returning 0
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@outgoing_pd:102] NoOp("Local/99737345@outgoing_pd-f327;1", "SipUser=tmgClient028") in new stack
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@outgoing_pd:103] Macro("Local/99737345@outgoing_pd-f327;1", "local-pd-agent") in new stack
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@macro-local-pd-agent:1] Macro("Local/99737345@outgoing_pd-f327;1", "record-on,99737345,DanielCliffe,Bokklubben_nysalg,ny_08122011,1324029756173357") in new stack
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@macro-record-on:1] Set("Local/99737345@outgoing_pd-f327;1", "MONITOR_DIRNAME=/var/tmg/record/dump/tmgpd") in new stack
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@macro-record-on:2] Set("Local/99737345@outgoing_pd-f327;1", "MONITOR_FILENAME=/var/tmg/record/dump/tmgpd/rec_99737345_16122011_110310_1324029756173357") in new stack
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@macro-record-on:3] MixMonitor("Local/99737345@outgoing_pd-f327;1", "/var/tmg/record/dump/tmgpd/rec_99737345_16122011_110310_1324029756173357.wav,av(0)V(0),lame --preset voice -v -B 64 -a /var/tmg/record/dump/tmgpd/rec_99737345_16122011_110310_1324029756173357.wav && rm -f /var/tmg/record/dump/tmgpd/rec_99737345_16122011_110310_1324029756173357.wav") in new stack
[Dec 16 11:03:10] VERBOSE[9959] app_mixmonitor.c: == Begin MixMonitor Recording Local/99737345@outgoing_pd-f327;1
[Dec 16 11:03:10] VERBOSE[9657] pbx.c: -- Executing [s@macro-local-pd-agent:2] Dial("Local/99737345@outgoing_pd-f327;1", "SIP/tmgClient028,20") in new stack
[Dec 16 11:03:10] VERBOSE[9657] netsock.c: == Using SIP RTP TOS bits 184
[Dec 16 11:03:10] VERBOSE[9657] netsock.c: == Using SIP RTP CoS mark 5
[Dec 16 11:03:10] WARNING[9657] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:10] WARNING[9657] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:10] VERBOSE[9657] app_dial.c: -- Called tmgClient028
[Dec 16 11:03:10] VERBOSE[9657] app_dial.c: -- SIP/tmgClient028-00000e78 answered Local/99737345@outgoing_pd-f327;1
[Dec 16 11:03:10] VERBOSE[9658] pbx.c: == Spawn extension (outgoing_pd, 99737345, 2) exited non-zero on 'Local/99737345@outgoing_pd-f327;2'
[Dec 16 11:03:11] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029791
[Dec 16 11:03:12] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029792
[Dec 16 11:03:13] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030244, mtime: 1324029779, now: 1324029793
[Dec 16 11:03:14] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available

COMMENT: pbx_spool.c is finally processing 11223344. 12 secs after iit was written to spool at 11:02:59

[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Running scan service for /var/spool/asterisk/outgoing/11223344
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Filename: /var/spool/asterisk/outgoing/11223344, Retries: 0, max: 0
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Starting call thread for /var/spool/asterisk/outgoing/11223344
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 1324030094, mtime: 1324030320, now: 1324029794
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99631440 next: 1324030094, mtime: 1324030244, now: 1324029794
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/91529685 next: 1324030094, mtime: 1324030337, now: 1324029794
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99645668 next: 1324030094, mtime: 1324030280, now: 1324029794
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99731742 next: 1324030094, mtime: 1324030319, now: 1324029794
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Running scan service for /var/spool/asterisk/outgoing/97491111
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Filename: /var/spool/asterisk/outgoing/97491111, Retries: 0, max: 0
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Starting call thread for /var/spool/asterisk/outgoing/97491111
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99737345 next: 1324030094, mtime: 1324030364, now: 1324029794
[Dec 16 11:03:14] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/12345678 next: 1324030094, mtime: 1324030370, now: 1324029794

COMMENT: Here call to 11223344.
[Dec 16 11:03:14] VERBOSE[9970] pbx_spool.c: -- Attempting call on local/11223344@outgoing_pd for s@outgoing_pd:100 (Retry 1)
[Dec 16 11:03:14] VERBOSE[9971] pbx_spool.c: -- Attempting call on local/97491111@outgoing_pd for s@outgoing_pd:100 (Retry 1)
[Dec 16 11:03:14] VERBOSE[9972] pbx.c: -- Executing [97491111@outgoing_pd:1] NoOp("Local/97491111@outgoing_pd-8088;2", " Callid:'97491111' WaitTime:'35'") in new stack
[Dec 16 11:03:14] VERBOSE[9972] pbx.c: -- Executing [97491111@outgoing_pd:2] Dial("Local/97491111@outgoing_pd-8088;2", "SIP/phonect/97491111,35,rwt") in new stack
[Dec 16 11:03:14] VERBOSE[9973] pbx.c: -- Executing [11223344@outgoing_pd:1] NoOp("Local/11223344@outgoing_pd-61e2;2", " Callid:'11223344' WaitTime:'21'") in new stack
[Dec 16 11:03:14] VERBOSE[9973] pbx.c: -- Executing [11223344@outgoing_pd:2] Dial("Local/11223344@outgoing_pd-61e2;2", "SIP/phonect/11223344,21,rwt") in new stack
[Dec 16 11:03:14] VERBOSE[9972] netsock.c: == Using SIP RTP TOS bits 184
[Dec 16 11:03:14] VERBOSE[9972] netsock.c: == Using SIP RTP CoS mark 5
[Dec 16 11:03:14] VERBOSE[9973] netsock.c: == Using SIP RTP TOS bits 184
[Dec 16 11:03:14] VERBOSE[9973] netsock.c: == Using SIP RTP CoS mark 5
[Dec 16 11:03:14] WARNING[9972] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:14] WARNING[9972] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:14] WARNING[9973] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:14] WARNING[9973] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:14] VERBOSE[9972] app_dial.c: -- Called phonect/97491111
[Dec 16 11:03:14] VERBOSE[9973] app_dial.c: -- Called phonect/11223344
[Dec 16 11:03:14] VERBOSE[9657] pbx.c: -- Executing [h@macro-local-pd-agent:1] AGI("SIP/phonect-00000e76", "controllerChannel,11300 hangup:99737345") in new stack
[Dec 16 11:03:14] VERBOSE[9657] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/controllerChannel
[Dec 16 11:03:14] VERBOSE[9657] res_agi.c: -- <SIP/phonect-00000e76>AGI Script controllerChannel completed, returning 0
[Dec 16 11:03:14] VERBOSE[9657] pbx.c: -- Executing [h@macro-local-pd-agent:2] Hangup("SIP/phonect-00000e76", "") in new stack
[Dec 16 11:03:14] VERBOSE[9657] features.c: == Spawn extension (macro-local-pd-agent, h, 2) exited non-zero on 'SIP/phonect-00000e76'
[Dec 16 11:03:14] VERBOSE[9657] app_macro.c: == Spawn extension (macro-local-pd-agent, s, 2) exited non-zero on 'SIP/phonect-00000e76' in macro 'local-pd-agent'
[Dec 16 11:03:14] VERBOSE[9657] pbx.c: == Spawn extension (outgoing_pd, s, 103) exited non-zero on 'SIP/phonect-00000e76'
[Dec 16 11:03:14] VERBOSE[9959] app_mixmonitor.c: == MixMonitor close filestream
[Dec 16 11:03:14] NOTICE[9657] pbx_spool.c: Call completed to local/99737345@outgoing_pd
[Dec 16 11:03:14] VERBOSE[9959] app_mixmonitor.c: == Executing [lame --preset voice -v -B 64 -a /var/tmg/record/dump/tmgpd/rec_99737345_16122011_110310_1324029756173357.wav && rm -f /var/tmg/record/dump/tmgpd/rec_99737345_16122011_110310_1324029756173357.wav]
[Dec 16 11:03:14] VERBOSE[9959] app_mixmonitor.c: == End MixMonitor Recording Local/99737345@outgoing_pd-f327;1
[Dec 16 11:03:15] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/11223344 next: 0, mtime: 1324030394, now: 1324029795
[Dec 16 11:03:15] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 1324030394, mtime: 1324030320, now: 1324029795
[Dec 16 11:03:15] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99631440 next: 1324030320, mtime: 1324030244, now: 1324029795
[Dec 16 11:03:15] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/91529685 next: 1324030244, mtime: 1324030337, now: 1324029795
[Dec 16 11:03:15] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99645668 next: 1324030244, mtime: 1324030280, now: 1324029795
[Dec 16 11:03:15] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99731742 next: 1324030244, mtime: 1324030319, now: 1324029795
[Dec 16 11:03:15] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/97491111 next: 1324030244, mtime: 1324030394, now: 1324029795
[Dec 16 11:03:15] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/12345678 next: 1324030244, mtime: 1324030370, now: 1324029795
[Dec 16 11:03:15] VERBOSE[9972] app_dial.c: -- SIP/phonect-00000e79 is making progress passing it to Local/97491111@outgoing_pd-8088;2
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/11223344 next: 0, mtime: 1324030394, now: 1324029796
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 1324030394, mtime: 1324030320, now: 1324029796
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Running scan service for /var/spool/asterisk/outgoing/99739967
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Filename: /var/spool/asterisk/outgoing/99739967, Retries: 0, max: 0
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Starting call thread for /var/spool/asterisk/outgoing/99739967
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99631440 next: 1324030096, mtime: 1324030244, now: 1324029796
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/91529685 next: 1324030096, mtime: 1324030337, now: 1324029796
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99645668 next: 1324030096, mtime: 1324030280, now: 1324029796
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99731742 next: 1324030096, mtime: 1324030319, now: 1324029796
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/97491111 next: 1324030096, mtime: 1324030394, now: 1324029796
[Dec 16 11:03:16] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/12345678 next: 1324030096, mtime: 1324030370, now: 1324029796
[Dec 16 11:03:16] VERBOSE[9978] pbx_spool.c: -- Attempting call on local/99739967@outgoing_pd for s@outgoing_pd:100 (Retry 1)
[Dec 16 11:03:16] VERBOSE[9979] pbx.c: -- Executing [99739967@outgoing_pd:1] NoOp("Local/99739967@outgoing_pd-72e2;2", " Callid:'99739967' WaitTime:'35'") in new stack
[Dec 16 11:03:16] VERBOSE[9979] pbx.c: -- Executing [99739967@outgoing_pd:2] Dial("Local/99739967@outgoing_pd-72e2;2", "SIP/phonect/99739967,35,rwt") in new stack
[Dec 16 11:03:16] VERBOSE[9979] netsock.c: == Using SIP RTP TOS bits 184
[Dec 16 11:03:16] VERBOSE[9979] netsock.c: == Using SIP RTP CoS mark 5
[Dec 16 11:03:16] WARNING[9979] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:16] WARNING[9979] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:16] VERBOSE[9979] app_dial.c: -- Called phonect/99739967
[Dec 16 11:03:17] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030096, mtime: 1324029795, now: 1324029797
[Dec 16 11:03:17] VERBOSE[9973] app_dial.c: -- SIP/phonect-00000e7a is making progress passing it to Local/11223344@outgoing_pd-61e2;2
[Dec 16 11:03:18] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030096, mtime: 1324029795, now: 1324029798
[Dec 16 11:03:19] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:19] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030096, mtime: 1324029795, now: 1324029799
[Dec 16 11:03:20] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030096, mtime: 1324029795, now: 1324029800
[Dec 16 11:03:20] VERBOSE[9979] app_dial.c: -- SIP/phonect-00000e7b is making progress passing it to Local/99739967@outgoing_pd-72e2;2
[Dec 16 11:03:21] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030096, mtime: 1324029795, now: 1324029801
[Dec 16 11:03:22] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030096, mtime: 1324029795, now: 1324029802
[Dec 16 11:03:23] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030096, mtime: 1324029795, now: 1324029803
[Dec 16 11:03:24] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:24] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030096, mtime: 1324029795, now: 1324029804
[Dec 16 11:03:25] VERBOSE[9667] app_dial.c: -- Nobody picked up in 35000 ms
[Dec 16 11:03:25] VERBOSE[9667] pbx.c: -- Executing [12345678@outgoing_pd:3] Goto("Local/12345678@outgoing_pd-0661;2", "s-NOANSWER,1") in new stack
[Dec 16 11:03:25] VERBOSE[9667] pbx.c: -- Goto (outgoing_pd,s-NOANSWER,1)
[Dec 16 11:03:25] VERBOSE[9667] pbx.c: -- Executing [s-NOANSWER@outgoing_pd:1] NoOp("Local/12345678@outgoing_pd-0661;2", "NOANSWER DIALSTATUS=NOANSWER Hangupcause=0") in new stack
[Dec 16 11:03:25] VERBOSE[9667] pbx.c: -- Executing [s-NOANSWER@outgoing_pd:2] AGI("Local/12345678@outgoing_pd-0661;2", "controllerChannel,11300 termination:12345678:dialStatus:NOANSWER:hangupCause:=0") in new stack
[Dec 16 11:03:25] VERBOSE[9667] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/controllerChannel
[Dec 16 11:03:25] VERBOSE[9667] res_agi.c: -- <Local/12345678@outgoing_pd-0661;2>AGI Script controllerChannel completed, returning 0
[Dec 16 11:03:25] VERBOSE[9667] pbx.c: -- Executing [s-NOANSWER@outgoing_pd:3] Hangup("Local/12345678@outgoing_pd-0661;2", "") in new stack
[Dec 16 11:03:25] VERBOSE[9667] pbx.c: == Spawn extension (outgoing_pd, s-NOANSWER, 3) exited non-zero on 'Local/12345678@outgoing_pd-0661;2'
[Dec 16 11:03:25] VERBOSE[9666] pbx.c: -- Executing [failed@outgoing_pd:1] NoOp("OutgoingSpoolFailed", "======== CALLFILE FAILED to 12345678 failed 1") in new stack
[Dec 16 11:03:25] VERBOSE[9666] pbx.c: -- Auto fallthrough, channel 'OutgoingSpoolFailed' status is 'UNKNOWN'
[Dec 16 11:03:25] NOTICE[9666] pbx_spool.c: Call failed to go through, reason (1) Hangup
[Dec 16 11:03:25] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/11223344 next: 0, mtime: 1324030394, now: 1324029805
[Dec 16 11:03:25] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 1324030394, mtime: 1324030320, now: 1324029805
[Dec 16 11:03:25] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99739967 next: 1324030320, mtime: 1324030396, now: 1324029805
[Dec 16 11:03:25] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99631440 next: 1324030320, mtime: 1324030244, now: 1324029805
[Dec 16 11:03:25] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/91529685 next: 1324030244, mtime: 1324030337, now: 1324029805
[Dec 16 11:03:25] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99645668 next: 1324030244, mtime: 1324030280, now: 1324029805
[Dec 16 11:03:25] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99731742 next: 1324030244, mtime: 1324030319, now: 1324029805
[Dec 16 11:03:25] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/97491111 next: 1324030244, mtime: 1324030394, now: 1324029805
[Dec 16 11:03:26] VERBOSE[8932] pbx.c: -- Executing [h@macro-local-pd-agent:1] AGI("SIP/phonect-00000e57", "controllerChannel,11300 hangup:99645668") in new stack
[Dec 16 11:03:26] VERBOSE[8932] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/controllerChannel
[Dec 16 11:03:26] VERBOSE[8932] res_agi.c: -- <SIP/phonect-00000e57>AGI Script controllerChannel completed, returning 0
[Dec 16 11:03:26] VERBOSE[8932] pbx.c: -- Executing [h@macro-local-pd-agent:2] Hangup("SIP/phonect-00000e57", "") in new stack
[Dec 16 11:03:26] VERBOSE[8932] features.c: == Spawn extension (macro-local-pd-agent, h, 2) exited non-zero on 'SIP/phonect-00000e57'
[Dec 16 11:03:26] VERBOSE[8932] app_macro.c: == Spawn extension (macro-local-pd-agent, s, 2) exited non-zero on 'SIP/phonect-00000e57' in macro 'local-pd-agent'
[Dec 16 11:03:26] VERBOSE[8932] pbx.c: == Spawn extension (outgoing_pd, s, 103) exited non-zero on 'SIP/phonect-00000e57'
[Dec 16 11:03:26] NOTICE[8932] pbx_spool.c: Call completed to local/99645668@outgoing_pd
[Dec 16 11:03:26] VERBOSE[8962] app_mixmonitor.c: == MixMonitor close filestream
[Dec 16 11:03:26] VERBOSE[8962] app_mixmonitor.c: == Executing [lame --preset voice -v -B 64 -a /var/tmg/record/dump/tmgpd/rec_99645668_16122011_110140_1324029679195116.wav && rm -f /var/tmg/record/dump/tmgpd/rec_99645668_16122011_110140_1324029679195116.wav]
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/11223344 next: 0, mtime: 1324030394, now: 1324029806
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 1324030394, mtime: 1324030320, now: 1324029806
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99739967 next: 1324030320, mtime: 1324030396, now: 1324029806
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99631440 next: 1324030320, mtime: 1324030244, now: 1324029806
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/91529685 next: 1324030244, mtime: 1324030337, now: 1324029806
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99731742 next: 1324030244, mtime: 1324030319, now: 1324029806
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Running scan service for /var/spool/asterisk/outgoing/93432131
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Filename: /var/spool/asterisk/outgoing/93432131, Retries: 0, max: 0
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Starting call thread for /var/spool/asterisk/outgoing/93432131
[Dec 16 11:03:26] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/97491111 next: 1324030106, mtime: 1324030394, now: 1324029806
[Dec 16 11:03:26] VERBOSE[10252] pbx_spool.c: -- Attempting call on local/93432131@outgoing_pd for s@outgoing_pd:100 (Retry 1)
[Dec 16 11:03:26] VERBOSE[10253] pbx.c: -- Executing [93432131@outgoing_pd:1] NoOp("Local/93432131@outgoing_pd-4a68;2", " Callid:'93432131' WaitTime:'35'") in new stack
[Dec 16 11:03:26] VERBOSE[10253] pbx.c: -- Executing [93432131@outgoing_pd:2] Dial("Local/93432131@outgoing_pd-4a68;2", "SIP/phonect/93432131,35,rwt") in new stack
[Dec 16 11:03:26] VERBOSE[10253] netsock.c: == Using SIP RTP TOS bits 184
[Dec 16 11:03:26] VERBOSE[10253] netsock.c: == Using SIP RTP CoS mark 5
[Dec 16 11:03:26] WARNING[10253] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:26] WARNING[10253] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:26] VERBOSE[10253] app_dial.c: -- Called phonect/93432131
[Dec 16 11:03:26] VERBOSE[8962] app_mixmonitor.c: == End MixMonitor Recording Local/99645668@outgoing_pd-89c9;1
[Dec 16 11:03:27] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030106, mtime: 1324029806, now: 1324029807
[Dec 16 11:03:28] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030106, mtime: 1324029806, now: 1324029808
[Dec 16 11:03:29] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:29] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030106, mtime: 1324029806, now: 1324029809
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/11223344 next: 0, mtime: 1324030394, now: 1324029810
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 1324030394, mtime: 1324030320, now: 1324029810
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99739967 next: 1324030320, mtime: 1324030396, now: 1324029810
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99631440 next: 1324030320, mtime: 1324030244, now: 1324029810
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Running scan service for /var/spool/asterisk/outgoing/99742315
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Filename: /var/spool/asterisk/outgoing/99742315, Retries: 0, max: 0
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Starting call thread for /var/spool/asterisk/outgoing/99742315
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/91529685 next: 1324030110, mtime: 1324030337, now: 1324029810
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99731742 next: 1324030110, mtime: 1324030319, now: 1324029810
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/93432131 next: 1324030110, mtime: 1324030406, now: 1324029810
[Dec 16 11:03:30] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/97491111 next: 1324030110, mtime: 1324030394, now: 1324029810
[Dec 16 11:03:30] VERBOSE[10267] pbx_spool.c: -- Attempting call on local/99742315@outgoing_pd for s@outgoing_pd:100 (Retry 1)
[Dec 16 11:03:30] VERBOSE[10268] pbx.c: -- Executing [99742315@outgoing_pd:1] NoOp("Local/99742315@outgoing_pd-2907;2", " Callid:'99742315' WaitTime:'35'") in new stack
[Dec 16 11:03:30] VERBOSE[10268] pbx.c: -- Executing [99742315@outgoing_pd:2] Dial("Local/99742315@outgoing_pd-2907;2", "SIP/phonect/99742315,35,rwt") in new stack
[Dec 16 11:03:30] VERBOSE[10268] netsock.c: == Using SIP RTP TOS bits 184
[Dec 16 11:03:30] VERBOSE[10268] netsock.c: == Using SIP RTP CoS mark 5
[Dec 16 11:03:30] WARNING[10268] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:30] WARNING[10268] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:30] VERBOSE[10268] app_dial.c: -- Called phonect/99742315
[Dec 16 11:03:30] VERBOSE[10253] app_dial.c: -- SIP/phonect-00000e7c is making progress passing it to Local/93432131@outgoing_pd-4a68;2
[Dec 16 11:03:31] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030110, mtime: 1324029809, now: 1324029811
[Dec 16 11:03:32] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030110, mtime: 1324029809, now: 1324029812
[Dec 16 11:03:32] VERBOSE[9972] app_dial.c: -- SIP/phonect-00000e79 is making progress passing it to Local/97491111@outgoing_pd-8088;2
[Dec 16 11:03:33] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030110, mtime: 1324029809, now: 1324029813
[Dec 16 11:03:33] VERBOSE[10268] app_dial.c: -- SIP/phonect-00000e7d is making progress passing it to Local/99742315@outgoing_pd-2907;2
[Dec 16 11:03:34] WARNING[6353] config.c: Realtime mapping for 'queues' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:34] DEBUG[4509] pbx_spool.c: Check is not executed. next: 1324030110, mtime: 1324029809, now: 1324029814
[Dec 16 11:03:34] VERBOSE[6343] netsock.c: == Using SIP RTP TOS bits 184
[Dec 16 11:03:34] VERBOSE[6343] netsock.c: == Using SIP RTP CoS mark 5
[Dec 16 11:03:34] WARNING[6343] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:34] WARNING[6343] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:34] WARNING[6343] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:34] WARNING[6343] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:34] WARNING[6343] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:34] WARNING[6343] config.c: Realtime mapping for 'extensions' found to engine 'mysql', but the engine is not available
[Dec 16 11:03:34] NOTICE[6343] chan_sip.c: Call from '4762202259' to extension '4769791072' rejected because extension not found in context 'from-sip-trunk'.
[Dec 16 11:03:35] VERBOSE[9973] app_dial.c: -- Nobody picked up in 21000 ms
[Dec 16 11:03:35] VERBOSE[9973] pbx.c: -- Executing [11223344@outgoing_pd:3] Goto("Local/11223344@outgoing_pd-61e2;2", "s-NOANSWER,1") in new stack
[Dec 16 11:03:35] VERBOSE[9973] pbx.c: -- Goto (outgoing_pd,s-NOANSWER,1)
[Dec 16 11:03:35] VERBOSE[9973] pbx.c: -- Executing [s-NOANSWER@outgoing_pd:1] NoOp("Local/11223344@outgoing_pd-61e2;2", "NOANSWER DIALSTATUS=NOANSWER Hangupcause=0") in new stack
[Dec 16 11:03:35] VERBOSE[9973] pbx.c: -- Executing [s-NOANSWER@outgoing_pd:2] AGI("Local/11223344@outgoing_pd-61e2;2", "controllerChannel,11300 termination:11223344:dialStatus:NOANSWER:hangupCause:=0") in new stack
[Dec 16 11:03:35] VERBOSE[9973] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/controllerChannel
[Dec 16 11:03:35] VERBOSE[9973] res_agi.c: -- <Local/11223344@outgoing_pd-61e2;2>AGI Script controllerChannel completed, returning 0
[Dec 16 11:03:35] VERBOSE[9973] pbx.c: -- Executing [s-NOANSWER@outgoing_pd:3] Hangup("Local/11223344@outgoing_pd-61e2;2", "") in new stack
[Dec 16 11:03:35] VERBOSE[9973] pbx.c: == Spawn extension (outgoing_pd, s-NOANSWER, 3) exited non-zero on 'Local/11223344@outgoing_pd-61e2;2'
[Dec 16 11:03:35] VERBOSE[9970] pbx.c: -- Executing [failed@outgoing_pd:1] NoOp("OutgoingSpoolFailed", "======== CALLFILE FAILED to 11223344 failed 1") in new stack
[Dec 16 11:03:35] VERBOSE[9970] pbx.c: -- Auto fallthrough, channel 'OutgoingSpoolFailed' status is 'UNKNOWN'
[Dec 16 11:03:35] NOTICE[9970] pbx_spool.c: Call failed to go through, reason (1) Hangup
[Dec 16 11:03:35] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/92070495 next: 0, mtime: 1324030320, now: 1324029815
[Dec 16 11:03:35] DEBUG[4509] pbx_spool.c: Timestamp disqualified /var/spool/asterisk/outgoing/99739967 next: 1324030320, mtime: 1324030396, now: 1324029815
{noformat}

Comments: By: Walter Doekes (wdoekes) 2011-12-20 02:26:20.276-0600

Hm.. it may be that you're on to something there.

{code}
if ((st.st_mtime == last) && (next && (next > now))) {
ast_log(LOG_DEBUG, "Check is not executed. next: %ld, mtime: %ld, now: %ld\n", next, st.st_mtime, now);
continue;
}
{code}

Create a file at t=3.2

dir-mtime = 3.2
file-mtime = 3.2

Read spool dir at t=3.3, file is set to run in future (+10 secs):

next = 13.2

Write new file at t=3.4

dir-mtime = 3.4
file2-mtime = 3.4

Re-enter loop:

3 ((int)dir-mtime == 3 ((int)last-dir-mtime) AND 13.2 (next) > 4.3 (new-now)

Result: skip the loop until either (int)mtime changes OR (next <= now)

However, you are using 1.6.2.x or lower, so you'll need to reproduce this with 1.8.x or higher to get support.

Regards,
Walter

P.S. Adding a debug statement just after the readdir, printing fn, would help the observer see that the file really isn't there yet in the first run.
By: Matt Jordan (mjordan) 2011-12-27 07:23:42.388-0600

As Walter asked, can you confirm if this is occurring in 1.8?
By: Knut Bakke (knutbakke) 2011-12-28 02:08:38.944-0600

It has not been tested on 1.8, not deploied yet. Will go 1.8 during Feb2012.
BR Knut B.
By: Matt Jordan (mjordan) 2011-12-30 15:31:09.831-0600

Code hasn't changed since 1.6.2, and Walter's comment makes sense - although you'd have to be writing multiple call files fast for that to occur.
By: Richard Mudgett (rmudgett) 2012-01-23 16:48:35.990-0600

See reviewboard patch:
https://reviewboard.asterisk.org/r/1688/

The critical change is to the if test pointed out by Walter.
By: Richard Mudgett (rmudgett) 2012-01-26 11:47:06.961-0600

[^jira_asterisk_19081_v1.6.2.patch] will apply to any v1.6.x since this section of code has not changed.

Please test as the v1.8 code has this old method and a newer method that uses inotify.
By: Richard Mudgett (rmudgett) 2012-02-03 18:12:28.824-0600

Ping.

Can you test the v1.6.2 version?

I created the v1.6.2 version because the v1.8 code has an alternate method that is likely to be active instead of the old method that was only available in v1.6.2 and earlier.