Attempted calls to random numbers originated by DAHDI channels

stefanocorsi68 · May 5, 2014, 10:45pm

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*41112532124152112361@from-group-10xx: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 [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("DAHDI/10-1", "AMPUSER=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid:3] GotoIf("DAHDI/10-1", "0?report") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("DAHDI/10-1", "AMPUSER=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid:6] Set("DAHDI/10-1", "AMPUSERCIDNAME=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid:7] GotoIf("DAHDI/10-1", "0?report") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid:8] Set("DAHDI/10-1", "AMPUSERCID=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid:9] Set("DAHDI/10-1", "__DIAL_OPTIONS=Ttr") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:11] GotoIf("DAHDI/10-1", "0?limit") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@sub-ccss:1] ExecIf("DAHDI/10-1", "0?Return()") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-ccss:2] Set("DAHDI/10-1", "CCSS_SETUP=TRUE") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-ccss: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 [monitor_default@sub-ccss:1] GotoIf("DAHDI/10-1", "0?is_exten") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [monitor_default@sub-ccss:2] StackPop("DAHDI/10-1", "") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [monitor_default@sub-ccss:3] Return("DAHDI/10-1", "FALSE") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:28] Set("DAHDI/10-1", "CALLERID(number)=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid:29] Set("DAHDI/10-1", "CALLERID(name)=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid:30] Set("DAHDI/10-1", "CDR(cnum)=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid:31] Set("DAHDI/10-1", "CDR(cnam)=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-user-callerid: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*41112532124152112361@from-group-10xx:2] Set("DAHDI/10-1", "MOHCLASS=default") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [3221*41112532124152112361@from-group-10xx:3] Set("DAHDI/10-1", "_NODEST=") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [3221*41112532124152112361@from-group-10xx: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check:7] Set("DAHDI/10-1", "__MON_FMT=wav") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check: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 [s@sub-record-check:11] ExecIf("DAHDI/10-1", "0?Return()") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check: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 [s@sub-record-check:13] GotoIf("DAHDI/10-1", "0?out,1") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check:14] Set("DAHDI/10-1", "__REC_STATUS=INITIALIZED") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check:15] Set("DAHDI/10-1", "NOW=1399092776") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check:16] Set("DAHDI/10-1", "__DAY=03") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check:17] Set("DAHDI/10-1", "__MONTH=05") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check:18] Set("DAHDI/10-1", "__YEAR=2014") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check:19] Set("DAHDI/10-1", "__TIMESTR=20140503-065256") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check:20] Set("DAHDI/10-1", "__FROMEXTEN=1010") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@sub-record-check: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 [s@sub-record-check: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 [out@sub-record-check: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 [out@sub-record-check: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 [out@sub-record-check:3] Return("DAHDI/10-1", "") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [3221*41112532124152112361@from-group-10xx: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 [s@macro-dialout-trunk:1] Set("DAHDI/10-1", "DIAL_TRUNK=3") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:3] GotoIf("DAHDI/10-1", "0?disabletrunk,1") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:7] GotoIf("DAHDI/10-1", "1?nomax") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("DAHDI/10-1", "0?skipoutcid") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:11] Macro("DAHDI/10-1", "outbound-callerid,3") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("DAHDI/10-1", "0?Set(CALLERPRES()=)") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:6] Set("DAHDI/10-1", "USEROUTCID=") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("DAHDI/10-1", "EMERGENCYCID=") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("DAHDI/10-1", "TRUNKOUTCID=") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:13] Set("DAHDI/10-1", "OUTNUM=3221*41112532124152112361") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("DAHDI/10-1", "custom=SIP/501") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk-predial-hook:1] MacroExit("DAHDI/10-1", "") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("DAHDI/10-1", "0?bypass,1") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:21] GotoIf("DAHDI/10-1", "0?customtrunk") in new stack
[2014-05-03 06:52:56] VERBOSE[1289][C-00002d71] pbx.c:     -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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'

dicko · May 6, 2014, 4:42am

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.

stefanocorsi68 · May 6, 2014, 6:36am

Thank you for your answer. Two things:

Why do you refer specifically to port 5666 (nagios)? Do you think the problem resides there?
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

SkykingOH · May 6, 2014, 8:31am

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.

stefanocorsi68 · May 6, 2014, 9:39am

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*41112532124152112361@from-group-10xx: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.

SkykingOH · May 6, 2014, 2:33pm

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.

stefanocorsi68 · May 7, 2014, 12:46pm

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?!

SkykingOH · May 7, 2014, 7:41pm

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.

kd4ned · May 7, 2014, 8:15pm

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.