Attempted calls to random numbers originated by DAHDI channels

Hi! I am experiencing a very frustrating problem with mysterious calls to non-significant and random numbers on an apparently uncompromised system. Below you’ll find a detailed description of the problem, system details and version, hardware details and relevant log snippets. In particular, at the end of this post, there’s a full log of a mysterious call originating to a non-existent 322141112532124152112361 number. The call reaches the SIP, but then it fails because, of course, there’s no 322141112532124152112361 number reachable on the phone network.

This problem is creating a lot of damage (please read below) so I would be very interested to hear from anyone who thinks he/she can help me diagnose the cause of these calls. I do not exclude an intrusion, but I’m very doubtful about that.

DESCRIPTION OF THE PROBLEM

In a random fashion, from DAHDI extensions leading to inhabited rooms of a hotel, some strange calls are attempted and sometimes successfully originated to apparently non significant numbers.

Numbers attempted to call are for example: 331, 31, 332, 221, 111, 112, 113, 32423*23432, etc…

The problem, apparently non damaging because actually the calls are not spending any money, is serious because one of the numbers reported above (112) is an emergency number for the italian police. The latter is getting quite annoyed to be called silently from the CID of my customer (the hotel).

The system is freshly installed, it is behind a firewall and, at least for what is my experience of hacked systems (and I’ve seen some) has not been hacked. There are no typical signs of intrusion (like missing log files, strange files around, strange open ports, etc… that doesn’t mean that the system cannot have been compromised, but it means for sure that IF it has been comprimised, the intruder has done a very good job to hide behind him/herself). Furthermore, the random numbers for which calls are originated don’t seem to indicate a malicious purpose.

It’s important to add that the strange behavious continues even when all cables are detached, that means that we could exclude any physical cause in the hotel rooms: there’s no physical connection from the DAHDI channels to the actual hotel rooms.

SOFTWARE DETAILS

The system is based on:

freepbx, 2.11.0-124 (schmooze)
Asterisk 11.7.0

NETWORK SETUP

The system is behind an apparently uncompromised firewall. A port scan on the system reveal these ports:

Starting Nmap 5.51 ( http://nmap.org ) at 2014-05-06 00:06 CEST Nmap scan report for localhost (127.0.0.1) Host is up (0.0000030s latency). Other addresses for localhost (not scanned): 127.0.0.1 Not shown: 985 closed ports PORT STATE SERVICE 22/tcp open ssh 25/tcp open smtp 53/tcp open domain 80/tcp open http 81/tcp open hosts2-ns 82/tcp open xfer 84/tcp open ctf 88/tcp open kerberos-sec 3306/tcp open mysql 5666/tcp open nrpe 8088/tcp open radan-http 50000/tcp open ibm-db2 50001/tcp open unknown 50002/tcp open iiimsf 50003/tcp open unknown

HARDWARE DETAILS

The PBX server mount two Wildcard TDM2400P with the following channel distribution:

Wildcard TDM2400P n. 1: 1-24 FXOKS
Wildcard TDM2400P n. 2: 1-3 empty, 4-8 FXSKS, 9-24 FXOKS

The cards give the following output (with some errors) during the boot stage:

May 5 23:47:43 localhost kernel: wctdm24xxp 0000:05:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 1: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 2: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 3: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 4: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 5: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 6: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 7: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 8: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 9: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 10: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 11: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 12: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 13: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 14: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 15: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 16: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 17: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 18: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 19: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 20: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 21: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 22: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 23: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Port 24: Installed -- AUTO FXS/DPO May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:00.0: Found a Wildcard TDM: Wildcard TDM2400P (0 BRI spans, 24 analog channels) May 5 23:47:47 localhost kernel: wctdm24xxp 0000:05:01.0: PCI INT A -> GSI 18 (level, low) -> IRQ 18 May 5 23:47:48 localhost 'dahdi_handle_device'[1134]: auto_assign_spans=1. Skip /devices/pci0000:00/0000:00:1c.5/0000:04:00.0/0000:05:00.0/pci:0000:05:00.0 May 5 23:47:48 localhost 'dahdi_span_config'[1142]: auto_assign_spans=1. Skip /devices/pci0000:00/0000:00:1c.5/0000:04:00.0/0000:05:00.0/pci:0000:05:00.0/span-1 May 5 23:47:48 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:48 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:48 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:48 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:48 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:48 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:48 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:48 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:49 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:49 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:49 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:49 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:49 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:49 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:49 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:49 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:50 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 17, resetting! May 5 23:47:50 localhost kernel: wctdm24xxp 0000:05:00.0: Power alarm on module 19, resetting! May 5 23:47:50 localhost kernel: wctdm24xxp 0000:05:00.0: Too many power alarms on card 17, NOT resetting! May 5 23:47:50 localhost kernel: wctdm24xxp 0000:05:00.0: Too many power alarms on card 19, NOT resetting! May 5 23:47:51 localhost kernel: wctdm24xxp 0000:05:01.0: ProSLIC on module 14 failed to powerup within 504 ms (375 mV only) May 5 23:47:51 localhost kernel: May 5 23:47:51 localhost kernel: -- DID YOU REMEMBER TO PLUG IN THE HD POWER CABLE TO THE TDM CARD?? May 5 23:47:51 localhost kernel: wctdm24xxp 0000:05:01.0: Unable to do INITIAL ProSLIC powerup on module 14 May 5 23:47:51 localhost kernel: wctdm24xxp 0000:05:01.0: ProSLIC on module 14 failed to powerup within 504 ms (375 mV only) May 5 23:47:51 localhost kernel: May 5 23:47:51 localhost kernel: -- DID YOU REMEMBER TO PLUG IN THE HD POWER CABLE TO THE TDM CARD?? May 5 23:47:51 localhost kernel: wctdm24xxp 0000:05:01.0: Unable to do INITIAL ProSLIC powerup on module 14 May 5 23:47:51 localhost kernel: wctdm24xxp 0000:05:01.0: Port 15: FAILED FXS (FCC) May 5 23:47:52 localhost kernel: wctdm24xxp 0000:05:01.0: ProSLIC on module 15 failed to powerup within 504 ms (0 mV only) May 5 23:47:52 localhost kernel: May 5 23:47:52 localhost kernel: -- DID YOU REMEMBER TO PLUG IN THE HD POWER CABLE TO THE TDM CARD?? May 5 23:47:52 localhost kernel: wctdm24xxp 0000:05:01.0: Unable to do INITIAL ProSLIC powerup on module 15 May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: ProSLIC on module 15 failed to powerup within 501 ms (0 mV only) May 5 23:47:53 localhost kernel: May 5 23:47:53 localhost kernel: -- DID YOU REMEMBER TO PLUG IN THE HD POWER CABLE TO THE TDM CARD?? May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Unable to do INITIAL ProSLIC powerup on module 15 May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 16: FAILED FXS (FCC) May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 1: Not installed May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 2: Not installed May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 3: Not installed May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 4: Not installed May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 5: Installed -- AUTO FXO (FCC mode) May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 6: Installed -- AUTO FXO (FCC mode) May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 7: Installed -- AUTO FXO (FCC mode) May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 8: Installed -- AUTO FXO (FCC mode) May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 9: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 10: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 11: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 12: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 13: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 14: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 15: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 16: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 17: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 18: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 19: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 20: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 21: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 22: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 23: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Port 24: Installed -- AUTO FXS/DPO May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Found a Wildcard TDM: Wildcard TDM2400P (0 BRI spans, 20 analog channels) May 5 23:47:53 localhost 'dahdi_handle_device'[1162]: auto_assign_spans=1. Skip /devices/pci0000:00/0000:00:1c.5/0000:04:00.0/0000:05:01.0/pci:0000:05:01.0 May 5 23:47:53 localhost 'dahdi_span_config'[1170]: auto_assign_spans=1. Skip /devices/pci0000:00/0000:00:1c.5/0000:04:00.0/0000:05:01.0/pci:0000:05:01.0/span-2 May 5 23:47:53 localhost kernel: vzaphfc: HFC-S PCI A ISDN (V1.42) loading May 5 23:47:53 localhost kernel: OPVXHW loaded May 5 23:47:53 localhost kernel: dahdi_transcode: Loaded. May 5 23:47:53 localhost kernel: wctdm24xxp 0000:05:01.0: Power alarm on module 24, resetting! May 5 23:47:53 localhost kernel: INFO-xpp: revision Unknown MAX_XPDS=64 (8*8) May 5 23:47:53 localhost kernel: INFO-xpp: FEATURE: with PROTOCOL_DEBUG May 5 23:47:53 localhost kernel: INFO-xpp: FEATURE: with sync_tick() from DAHDI May 5 23:47:53 localhost kernel: INFO-xpp_usb: revision Unknown May 5 23:47:53 localhost kernel: usbcore: registered new interface driver xpp_usb May 5 23:47:54 localhost kernel: wctdm24xxp 0000:05:01.0: Power alarm on module 24, resetting! May 5 23:47:54 localhost kernel: wctdm24xxp 0000:05:01.0: Power alarm on module 24, resetting! May 5 23:47:54 localhost kernel: wctdm24xxp 0000:05:01.0: Power alarm on module 24, resetting! May 5 23:47:55 localhost kernel: wctdm24xxp 0000:05:01.0: Power alarm on module 24, resetting! May 5 23:47:55 localhost kernel: wctdm24xxp 0000:05:01.0: Power alarm on module 24, resetting!

SIGNIFICANT LOG FILES

Following the log from an attempted misterious call:

[2014-05-03 06:52:33] VERBOSE[1289][C-00002d71] sig_analog.c: -- Starting simple switch on 'DAHDI/10-1' [2014-05-03 06:52:36] VERBOSE[1290][C-00002d72] sig_analog.c: -- Starting simple switch on 'DAHDI/20-1' [2014-05-03 06:52:38] VERBOSE[1290][C-00002d72] sig_analog.c: -- Hanging up on 'DAHDI/20-1' [2014-05-03 06:52:38] VERBOSE[1290][C-00002d72] chan_dahdi.c: -- Hungup 'DAHDI/20-1' [2014-05-03 06:52:38] VERBOSE[1291][C-00002d73] sig_analog.c: -- Starting simple switch on 'DAHDI/20-1' [2014-05-03 06:52:41] VERBOSE[1291][C-00002d73] sig_analog.c: -- Hanging up on 'DAHDI/20-1' [2014-05-03 06:52:41] VERBOSE[1291][C-00002d73] chan_dahdi.c: -- Hungup 'DAHDI/20-1' [2014-05-03 06:52:51] VERBOSE[1292][C-00002d74] sig_analog.c: -- Starting simple switch on 'DAHDI/20-1' [2014-05-03 06:52:53] VERBOSE[1292][C-00002d74] sig_analog.c: -- Hanging up on 'DAHDI/20-1' [2014-05-03 06:52:53] VERBOSE[1292][C-00002d74] chan_dahdi.c: -- Hungup 'DAHDI/20-1' [2014-05-03 06:52:55] VERBOSE[1293][C-00002d75] sig_analog.c: -- Starting simple switch on 'DAHDI/20-1' [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [3221*[email protected]:1] Macro("DAHDI/10-1", "user-callerid,LIMIT,EXTERNAL,") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:1] Set("DAHDI/10-1", "TOUCH_MONITOR=1399092753.12417") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:2] Set("DAHDI/10-1", "AMPUSER=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:3] GotoIf("DAHDI/10-1", "0?report") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:4] ExecIf("DAHDI/10-1", "1?Set(REALCALLERIDNUM=1010)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:5] Set("DAHDI/10-1", "AMPUSER=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:6] Set("DAHDI/10-1", "AMPUSERCIDNAME=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:7] GotoIf("DAHDI/10-1", "0?report") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:8] Set("DAHDI/10-1", "AMPUSERCID=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:9] Set("DAHDI/10-1", "__DIAL_OPTIONS=Ttr") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:10] Set("DAHDI/10-1", "CALLERID(all)="1010" <1010>") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:11] GotoIf("DAHDI/10-1", "0?limit") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:12] ExecIf("DAHDI/10-1", "1?Set(GROUP(concurrency_limit)=1010)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:13] ExecIf("DAHDI/10-1", "0?Set(CHANNEL(language)=)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:14] GosubIf("DAHDI/10-1", "7?sub-ccss,s,1(from-group-10xx,)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:1] ExecIf("DAHDI/10-1", "0?Return()") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:2] Set("DAHDI/10-1", "CCSS_SETUP=TRUE") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:3] GosubIf("DAHDI/10-1", "0?monitor_config,1(from-group-10xx,):monitor_default,1(from-group-10xx,)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:1] GotoIf("DAHDI/10-1", "0?is_exten") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:2] StackPop("DAHDI/10-1", "") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:3] Return("DAHDI/10-1", "FALSE") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:15] GotoIf("DAHDI/10-1", "1?continue") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Goto (macro-user-callerid,s,28) [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:28] Set("DAHDI/10-1", "CALLERID(number)=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:29] Set("DAHDI/10-1", "CALLERID(name)=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:30] Set("DAHDI/10-1", "CDR(cnum)=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:31] Set("DAHDI/10-1", "CDR(cnam)=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:32] Set("DAHDI/10-1", "CHANNEL(language)=en") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [3221*[email protected]:2] Set("DAHDI/10-1", "MOHCLASS=default") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [3221*[email protected]:3] Set("DAHDI/10-1", "_NODEST=") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [3221*[email protected]:4] Gosub("DAHDI/10-1", "sub-record-check,s,1(out,3221*41112532124152112361,)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:1] Set("DAHDI/10-1", "REC_POLICY_MODE_SAVE=") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:2] GotoIf("DAHDI/10-1", "1?check") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Goto (sub-record-check,s,7) [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:7] Set("DAHDI/10-1", "__MON_FMT=wav") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:8] GotoIf("DAHDI/10-1", "1?next") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Goto (sub-record-check,s,11) [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:11] ExecIf("DAHDI/10-1", "0?Return()") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:12] ExecIf("DAHDI/10-1", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:13] GotoIf("DAHDI/10-1", "0?out,1") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:14] Set("DAHDI/10-1", "__REC_STATUS=INITIALIZED") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:15] Set("DAHDI/10-1", "NOW=1399092776") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:16] Set("DAHDI/10-1", "__DAY=03") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:17] Set("DAHDI/10-1", "__MONTH=05") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:18] Set("DAHDI/10-1", "__YEAR=2014") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:19] Set("DAHDI/10-1", "__TIMESTR=20140503-065256") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:20] Set("DAHDI/10-1", "__FROMEXTEN=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:21] Set("DAHDI/10-1", "__CALLFILENAME=out-3221*41112532124152112361-1010-20140503-065256-1399092753.12417") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:22] Goto("DAHDI/10-1", "out,1") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Goto (sub-record-check,out,1) [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:1] ExecIf("DAHDI/10-1", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:2] GosubIf("DAHDI/10-1", "0?record,1(exten,3221*41112532124152112361,1010)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:3] Return("DAHDI/10-1", "") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [3221*[email protected]:5] Macro("DAHDI/10-1", "dialout-trunk,3,3221*41112532124152112361,,off") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:1] Set("DAHDI/10-1", "DIAL_TRUNK=3") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:2] GosubIf("DAHDI/10-1", "0?sub-pincheck,s,1()") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:3] GotoIf("DAHDI/10-1", "0?disabletrunk,1") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:4] Set("DAHDI/10-1", "DIAL_NUMBER=3221*41112532124152112361") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:5] Set("DAHDI/10-1", "DIAL_TRUNK_OPTIONS=Ttr") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:6] Set("DAHDI/10-1", "OUTBOUND_GROUP=OUT_3") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:7] GotoIf("DAHDI/10-1", "1?nomax") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:9] GotoIf("DAHDI/10-1", "0?skipoutcid") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:10] Set("DAHDI/10-1", "DIAL_TRUNK_OPTIONS=Tt") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:11] Macro("DAHDI/10-1", "outbound-callerid,3") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:1] ExecIf("DAHDI/10-1", "0?Set(CALLERPRES()=)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:2] ExecIf("DAHDI/10-1", "0?Set(REALCALLERIDNUM=1010)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:3] GotoIf("DAHDI/10-1", "1?normcid") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Goto (macro-outbound-callerid,s,6) [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:6] Set("DAHDI/10-1", "USEROUTCID=") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:7] Set("DAHDI/10-1", "EMERGENCYCID=") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:8] Set("DAHDI/10-1", "TRUNKOUTCID=") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:9] GotoIf("DAHDI/10-1", "1?trunkcid") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Goto (macro-outbound-callerid,s,14) [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:14] ExecIf("DAHDI/10-1", "0?Set(CALLERID(all)=)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:15] ExecIf("DAHDI/10-1", "0?Set(CALLERID(all)=)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:16] ExecIf("DAHDI/10-1", "0?Set(CALLERID(all)=)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:17] ExecIf("DAHDI/10-1", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:18] Set("DAHDI/10-1", "CDR(outbound_cnum)=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:19] Set("DAHDI/10-1", "CDR(outbound_cnam)=1010") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:12] GosubIf("DAHDI/10-1", "0?sub-flp-3,s,1()") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:13] Set("DAHDI/10-1", "OUTNUM=3221*41112532124152112361") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:14] Set("DAHDI/10-1", "custom=SIP/501") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:15] ExecIf("DAHDI/10-1", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:16] ExecIf("DAHDI/10-1", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:17] Macro("DAHDI/10-1", "dialout-trunk-predial-hook,") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:1] MacroExit("DAHDI/10-1", "") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:18] GotoIf("DAHDI/10-1", "0?bypass,1") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:19] ExecIf("DAHDI/10-1", "1?Set(CONNECTEDLINE(num,i)=3221*41112532124152112361)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:20] ExecIf("DAHDI/10-1", "1?Set(CONNECTEDLINE(name,i)=CID:1010)") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:21] GotoIf("DAHDI/10-1", "0?customtrunk") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:22] Dial("DAHDI/10-1", "SIP/501/3221*41112532124152112361,300,Tt") in new stack [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] netsock2.c: == Using SIP RTP TOS bits 184 [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] netsock2.c: == Using SIP RTP CoS mark 5 [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] app_dial.c: -- Called SIP/501/3221*41112532124152112361 [2014-05-03 06:52:57] VERBOSE[19773][C-00002d71] chan_sip.c: -- Got SIP response 484 "Address Incomplete" back from 10.0.0.2:5062 [2014-05-03 06:52:57] VERBOSE[1289][C-00002d71] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1) [2014-05-03 06:52:57] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [[email protected]:23] NoOp("DAHDI/10-1", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 28") in new stack

Other Excerpts from full.log

In the asterisk-full.log, there’s a continuous signalling from a channel that, by the way, is not usually connected to any cabling because it is damaged:

[2014-05-05 23:55:49] VERBOSE[2552][C-0000005f] sig_analog.c: -- Starting simple switch on 'DAHDI/20-1' [2014-05-05 23:55:53] VERBOSE[2552][C-0000005f] sig_analog.c: -- Hanging up on 'DAHDI/20-1' [2014-05-05 23:55:53] VERBOSE[2552][C-0000005f] chan_dahdi.c: -- Hungup 'DAHDI/20-1' [2014-05-05 23:55:54] VERBOSE[2553][C-00000060] sig_analog.c: -- Starting simple switch on 'DAHDI/20-1' [2014-05-05 23:55:56] VERBOSE[2553][C-00000060] sig_analog.c: -- Hanging up on 'DAHDI/20-1' [2014-05-05 23:55:56] VERBOSE[2553][C-00000060] chan_dahdi.c: -- Hungup 'DAHDI/20-1' [2014-05-05 23:55:56] VERBOSE[2554][C-00000061] sig_analog.c: -- Starting simple switch on 'DAHDI/20-1' [2014-05-05 23:55:58] VERBOSE[2554][C-00000061] sig_analog.c: -- Hanging up on 'DAHDI/20-1' [2014-05-05 23:55:58] VERBOSE[2554][C-00000061] chan_dahdi.c: -- Hungup 'DAHDI/20-1' [2014-05-05 23:55:59] VERBOSE[2555][C-00000062] sig_analog.c: -- Starting simple switch on 'DAHDI/20-1' [2014-05-05 23:56:02] VERBOSE[2555][C-00000062] sig_analog.c: -- Hanging up on 'DAHDI/20-1' [2014-05-05 23:56:02] VERBOSE[2555][C-00000062] chan_dahdi.c: -- Hungup 'DAHDI/20-1'

This is only likely to happen on a FreePBX distribution

5666/tcp open nrpe

you should take this discussion there for how to fix the whoopsie. It won’t happen to a general FreePBX install.

Thank you for your answer. Two things:

  1. Why do you refer specifically to port 5666 (nagios)? Do you think the problem resides there?

  2. Before I had a plain vanilla Freepbx installation and it still happened though it wasn’t so damaging because extension numbers (111,112,113, etc) we used at that time masked the emergency numbers. We only had random calls to extensions (hotel rooms). Now that we’ve changed the extension numbers to 1011, 1012, 1013, etc. the thing has become more serious because emergency services are being rung.

Thank you
Stefano

I have no idea why Dicko brought up Nagios.

The errors you are seeing are caused by the bad channel sending a ring or off hook indication to Asterisk via DAHDI, unplug the daughter board.

As far as the random calls. The users are probably hacking voice mail accounts.

Thank you SkykingOH for your answer. For what regarding the signaling error, the board comes with 6 modules with four channels on each one… I don’t know if I’ll manage to detach a single channel. I could try.

For what regarding hacking the voicemail… well… there are no users now… all cables are disconnected, the system is behind a firewall, the firewall only allows 22 and 443, all the server appear apparently non compromised.

The log (excerpts):

[2014-05-03 06:52:33] VERBOSE[1289][C-00002d71] sig_analog.c: -- Starting simple switch on 'DAHDI/10-1' [2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c: -- Executing [3221*[email protected]:1] Macro("DAHDI/10-1", "user-callerid,LIMIT,EXTERNAL,") in new stack

seems to indicate that there is a connection originating from channel 10 to number 3221*41112532124152112361.

Could such a connection attempt be originated from an electric signalling problem? Could the source be a hardware problem?

Thanks
S.

Yes, you can’t disable one channel on that board. Have to replace.

As far as the other issue. I don’t know? Very odd.

You could do a ‘core set debug 254’ and see the DAHDI messages.

Hello. After much trial and error troubleshooting, I’ve (maybe) discovered what was causing the random calls.

An fsx module of my TDM2400P was damaged, you could hear this when lifting the phone because it made lots of background noise. It was the same module to which channel 20 belonged. And channel 20 also produced the following continous trace in the logs:

[2014-05-03 06:52:38] VERBOSE[1291][C-00002d73] sig_analog.c: – Starting simple switch on ‘DAHDI/20-1’
[2014-05-03 06:52:41] VERBOSE[1291][C-00002d73] sig_analog.c: – Hanging up on ‘DAHDI/20-1’
[2014-05-03 06:52:41] VERBOSE[1291][C-00002d73] chan_dahdi.c: – Hungup ‘DAHDI/20-1’

At this point I noticed that if I lifted up and hung up very quickly many times the phone connected to channel 20, a call to a random number was originated.

After removal of the module, apparently, no calls have been originated, plus no trace has been produced in the log.

Can it be possible that a damaged module has such an impact on Asterisk and produces random signals that can be interpreted as a call originating?!

Sure, without a doubt. The conversion of analog to digital is not a perfect science. Hook states are communicated with resistance and voltage that has to be coded into specific bit states.

IIRC (been several years since I have used them), those analog cards actually support pulse dialing. (You can hook up an old rotary phone in one of the rooms and place calls through it.)

That said, if “something” is happening (be it a problem with the physical line, or just a damaged module as you suspect) to cause the line to transition on/off hook at random times, it’s totally possible that these transitions between on/off hook are taking place rapidly enough to be recognized as pulse dial digits.

If that’s the case, then you’ve got a plausible explanation for those random calls showing up in your CDRs.