1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.
  2. If you had a PIAF Forum account in the vBulletin days, log in with your old credentials. Otherwise, sign up again and we'll get you back in business as soon as we can.
  3. Guest: We think the problem with locked threads from long message subjects has been resolved. Post a link here if you still see a problem.
Cookies Welcome Back Long Message Subjects SOLVED

PBX Error

Discussion in 'Help' started by CoZZa, Dec 1, 2008.

  1. CoZZa New Member

    Hi,

    I have been running a PBX box for around a year now and havn't really had many problems until now.

    I come home to notice my SIP phones have lost registration.

    Checking under the sip registry:

    302 (Unspecified) D N 0 UNKNOWN
    301 (Unspecified) D N 0 UNKNOWN
    300 (Unspecified) D N 0 UNKNOWN
    When i try and make a change to anything in FreePBX it comes up with:

    Error: Did not receive valid response from server

    Any ideas on how to fix this?
    CoZZa, Dec 1, 2008
    #1

  2. wardmundy Nerd Uno

    Assuming you've already rebooted your Asterisk server AND your router, check /var/log/asterisk/full for errors.
    wardmundy, Dec 1, 2008
    #2

  3. CoZZa New Member

    Yep, have rebooted several times...

    After a reboot, the last 100 lines:

    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'ContinueWhile'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_while.so => (While Loops and Conditional Execution)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered custom function BLACKLIST
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'LookupBlacklist'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_lookupblacklist.so => (Look up Caller*ID name/number from blacklist database)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered custom function REALTIME
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: func_realtime.so => (Read/Write values from a RealTime repository)
    [Dec 1 21:55:00] NOTICE[2594] chan_skinny.c: Unable to load config skinny.conf, Skinny disabled
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'Read'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_read.so => (Read Variable Application)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered custom function VMCOUNT
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'HasVoicemail'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'HasNewVoicemail'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_hasnewvoicemail.so => (Indicator for whether a voice mailbox has messages in a given folder.)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'ZapSendKeypadFacility'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/zapata.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/zapata-channels.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/zapata_additional.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: -- Automatically generated pseudo channel
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered channel type 'Zap' (Zapata Telephony Driver w/PRI)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action ZapTransfer
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action ZapHangup
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action ZapDialOffhook
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action ZapDNDon
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action ZapDNDoff
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action ZapShowChannels
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action ZapRestart
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: chan_zap.so => (Zapata Telephony)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/res_mysql.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] DEBUG[2594] res_config_mysql.c: MySQL RealTime Host: 127.0.0.1
    [Dec 1 21:55:00] DEBUG[2594] res_config_mysql.c: MySQL RealTime Port: 3306
    [Dec 1 21:55:00] DEBUG[2594] res_config_mysql.c: MySQL RealTime User: root
    [Dec 1 21:55:00] DEBUG[2594] res_config_mysql.c: MySQL RealTime Password: passw0rd
    [Dec 1 21:55:00] DEBUG[2594] res_config_mysql.c: MySQL RealTime: Successfully connected to database.
    [Dec 1 21:55:00] NOTICE[2594] config.c: Registered Config Engine mysql
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: MySQL RealTime driver loaded.
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: res_config_mysql.so => (MySQL RealTime Configuration Driver)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/cdr_manager.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: cdr_manager.so => (Asterisk Manager Interface CDR Backend)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'WaitForRing'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_waitforring.so => (Waits until first ring after time)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'SendURL'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_url.so => (Send URL Applications)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'BackgroundDetect'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_talkdetect.so => (Playback with Talk Detection)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'SayUnixTime'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'DateTime'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_sayunixtime.so => (Say time)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered channel type 'DS' (Application for sending device state messages 1.4.3)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action DevState
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'DevState'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_devstate.so => (Control SNOM LED Device State)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'SMS'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_sms.so => (SMS/PSTN handler)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'Transfer'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_transfer.so => (Transfer)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'ZapRAS'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_zapras.so => (Zap RAS Application)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered file format g723sf, extension(s) g723|g723sf
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: format_g723.so => (G.723.1 Simple Timestamp File Format)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered custom function RAND
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: func_rand.so => (Random number dialplan function)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'PrivacyManager'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_privacy.so => (Require phone number to be entered, if no CallerID sent)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: res_clioriginate.so => (Call origination from the CLI)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered custom function ENUMLOOKUP
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered custom function TXTCIDNAME
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: func_enum.so => (ENUM related dialplan functions)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'Random'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_random.so => (Random goto)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'SetCDRUserField'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'AppendCDRUserField'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Manager registered action SetCDRUserField
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_setcdruserfield.so => (CDR user field apps)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered file format h264, extension(s) h264
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: format_h264.so => (Raw H.264 data)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered channel type 'Agent' (Call Agent Proxy Channel)
    [Dec 1 21:55:00] NOTICE[2594] chan_agent.c: No agent configuration found -- agent support disabled
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered custom function CDR
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: func_cdr.so => (CDR dialplan function)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: pbx_spool.so => (Outgoing Spool Support)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'Page'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_page.so => (Page Multiple Phones)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered custom function SHA1
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: func_sha1.so => (SHA-1 computation dialplan function)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Registered application 'SendImage'
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: app_image.so => (Image Transmission Application)
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip_general_additional.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip_general_custom.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip_nat.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip_registrations_custom.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip_registrations.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip_custom.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip_additional.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:00] VERBOSE[2594] logger.c: == Parsing '/etc/asterisk/sip_custom_post.conf': [Dec 1 21:55:00] VERBOSE[2594] logger.c: Found
    [Dec 1 21:55:05] VERBOSE[2680] logger.c: == Parsing '/etc/asterisk/manager.conf': [Dec 1 21:55:05] VERBOSE[2680] logger.c: Found
    [Dec 1 21:55:05] VERBOSE[2680] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Dec 1 21:55:05] VERBOSE[2680] logger.c: Found
    [Dec 1 21:55:05] VERBOSE[2680] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Dec 1 21:55:05] VERBOSE[2680] logger.c: Found
    [Dec 1 21:55:05] VERBOSE[2680] logger.c: == Manager 'admin' logged on from 127.0.0.1
    CoZZa, Dec 1, 2008
    #3

  4. CoZZa New Member

    Edit: Then goes on with:
    Dec 1 21:55:41] NOTICE[2594] pbx_ael.c: Starting AEL load process.
    [Dec 1 21:55:41] NOTICE[2594] pbx_ael.c: AEL load process: calculated config file name '/etc/asterisk/extensions.ael'.
    [Dec 1 21:55:41] NOTICE[2594] pbx_ael.c: File /etc/asterisk/extensions.ael not found; AEL declining load
    [Dec 1 21:55:41] VERBOSE[2594] logger.c: == Registered format 'jpg' (JPEG (Joint Picture Experts Group))
    [Dec 1 21:55:41] VERBOSE[2594] logger.c: format_jpeg.so => (JPEG (Joint Picture Experts Group) Image Format)
    [Dec 1 21:55:41] VERBOSE[2594] logger.c: Asterisk Ready.
    [Dec 1 21:55:41] NOTICE[2751] chan_sip.c: Peer 'MNF7020' is now Reachable. (99ms / 2000ms)
    [Dec 1 21:56:19] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:19] NOTICE[2751] chan_sip.c: Peer 'MNF6020' is now UNREACHABLE! Last qualify: 0
    [Dec 1 21:56:19] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:19] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:19] NOTICE[2751] chan_sip.c: Peer 'PT' is now UNREACHABLE! Last qualify: 0
    [Dec 1 21:56:19] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:19] NOTICE[2751] chan_sip.c: -- Registration for 'XXXXXXXX@sip01.mynetfone.com.au@sip01.mynetfone.com.au' timed out, trying again (Attempt #1)
    [Dec 1 21:56:29] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:29] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:29] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:29] NOTICE[2751] chan_sip.c: Peer '111-peer' is now UNREACHABLE! Last qualify: 0
    [Dec 1 21:56:29] NOTICE[2751] chan_sip.c: -- Registration for 'XXXXXXXX@sip.pennytel.com@sip.pennytel.com' timed out, trying again (Attempt #1)
    [Dec 1 21:56:40] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:40] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:40] NOTICE[2751] chan_sip.c: -- Registration for 'XXXXXXXX@sip00.mynetfone.com.au@sip00.mynetfone.com.au' timed out, trying again (Attempt #1)
    [Dec 1 21:56:50] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:50] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:50] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:50] DEBUG[2751] sched.c: Request to schedule in the past?!?!
    [Dec 1 21:56:50] NOTICE[2751] chan_sip.c: -- Registration for 'XXXXXXXX@sip01.mynetfone.com.au@sip01.mynetfone.com.au' timed out, trying again (Attempt #2)
    CoZZa, Dec 1, 2008
    #4

  5. wardmundy Nerd Uno

    Check the date and time settings on your machine. Then reboot and check logs again. Also looks like you have no Internet connectivity from the server.
    wardmundy, Dec 1, 2008
    #5

  6. CoZZa New Member

    Hey

    It has the correct time (Australia)

    root@pbx:~ $ date
    Mon Dec 1 22:41:14 EST 2008

    The internet is working from the box as I can ping out from it:

    PING pbxinaflash.com (74.86.141.169) 56(84) bytes of data.
    64 bytes from gw.wardmundy.com (74.86.141.169): icmp_seq=1 ttl=49 time=240 ms
    64 bytes from gw.wardmundy.com (74.86.141.169): icmp_seq=2 ttl=49 time=239 ms
    64 bytes from gw.wardmundy.com (74.86.141.169): icmp_seq=3 ttl=49 time=239 ms
    64 bytes from gw.wardmundy.com (74.86.141.169): icmp_seq=4 ttl=49 time=239 ms
    64 bytes from gw.wardmundy.com (74.86.141.169): icmp_seq=5 ttl=49 time=240 ms
    64 bytes from gw.wardmundy.com (74.86.141.169): icmp_seq=6 ttl=49 time=239 ms

    Local SIP phones won't connect into it either, plus when i try to reload config it doesn't work

    I'm stumped...
    CoZZa, Dec 1, 2008
    #6

  7. wardmundy Nerd Uno

    If this were a business phone system, I'd be reaching for my backup to restore. If not, hang in there until the rest of the U.S. gets out of bed. :wink5:
    wardmundy, Dec 1, 2008
    #7

  8. CoZZa New Member

    It is a business phone system to a point (home business, but after hours)

    I have setup the SIP account to go direct to the IP phone, but am thinking tomorrow evening if nobody has any ideas i might just re-build the box, won't take that long.

    Thanks for your help wardmundy :)
    CoZZa, Dec 1, 2008
    #8

  9. jroper Guru

    Hi

    These lines don't look right:-

    Registration for 'XXXXXXXX@sip01.mynetfone.com.au@sip01.mynetfone.c om.au


    too many @ symbols in them, and a gap in the .com which may be down to formatting.

    If you lose SIP registration with your trunks then the internal phones can drop out as well.

    You may also look at this topic. http://www.freepbx.org/forum/apply-configuration-changes.

    The other question to ask yourself is "What's changed in your network, PC or PBX?"

    Joe
    jroper, Dec 1, 2008
    #9

  10. CoZZa New Member

    Hi Joe,

    Nothing has changed recently. The only thing was on Saturday night there was a blackout, came back on file, has been working until this arvo and looks like its dropped everything.

    Nothing has changed network wise, I have rebooted switches, routers etc in case it had something to do with it, but everything else is working fine, network wise.

    The SIP details have been the same i have used all the time and what i got off a MNF Setup tutorial, as well as sample config that was sent by themselves.
    CoZZa, Dec 1, 2008
    #10

  11. jroper Guru

    I've had a power blackout corrupt /var/log/asterisk/full so that asterisk would not start, so I know blackouts can do some strange things, especially if you happen to be writing to a file when the power goes off.

    I'm really suspicious of those trunk registrations, they just do not look right. I'd delete the trunk registrations and recreate them.



    Joe
    jroper, Dec 1, 2008
    #11

Share This Page