Details

    • Type: Bug Bug
    • Status: Triage
    • Severity: Major Major
    • Resolution: Suspended
    • Affects Version/s: 14.6.0, 14.6.1
    • Target Release Version/s: None
    • Component/s: pjproject/pjsip
    • Security Level: None
    • Labels:
      None
    • Environment:
      Plus Freepbx 14.0.1.4 running on vultr.com with 2048 ram (had 1024 ram and upped it)

      Description

      Potentiallly related to closed ASTERISK-25653

      While I do have sip clients on cellular right now this is all occuring in-house over wifi or wired.
      My Asterisk 14/Freepbx14 is located on vultr and now is 2048GB ram up from 1024 ram last night

      Is anyone having weird issues with PJSIP? Since I migrated from ASterisk 13/Freepbx 12 I’ve had nothing but extensions dropping off. I was running on a 1024 RAM on Vultr and upped it to 2048 ram last night and TOP is showing me free memory keeps dropping:

      top - 10:21:35 up 12:16, 1 user, load average: 0.02, 0.13, 0.15
      Tasks: 107 total, 1 running, 106 sleeping, 0 stopped, 0 zombie
      %Cpu(s): 0.3 us, 0.3 sy, 0.0 ni, 99.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
      KiB Mem : 1883708 total, 212440 free, 778244 used, 893024 buff/cache
      KiB Swap: 2097148 total, 2094288 free, 2860 used. 790064 avail Mem
      

      This started off as about 650000 free last night. looking at a asterisk debug I see pjsip running out of memory. Before I go over to Asterisk on this has anyone been seeing anything weird?

      Thanks leon

      some of the asterisk debug

      [2017-09-06 09:45:48] ERROR[7284] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[3640] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[3640] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[3640] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[3640] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[7285] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[7285] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[7285] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[7285] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[7285] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 09:45:48] ERROR[2803] pjproject: ssl0x7f0b5c0ccd40 Renegotiation failed: Not enough memory (PJ_ENOMEM)
      [2017-09-06 09:45:48] VERBOSE[2809] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:45384;transport=TLS is now Unreachable. RTT: 0.000 msec
      [2017-09-06 09:54:06] VERBOSE[8236] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:38964;transport=TLS has been deleted
      [2017-09-06 09:56:06] VERBOSE[8236] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:45367;transport=TLS has been deleted
      [2017-09-06 09:59:30] VERBOSE[7602] pbx_variables.c: Setting global variable ‘SIPDOMAIN’ to ‘pbx.backwoodswireless.net’
      

      more interesting debugs:

      [2017-09-06 06:23:45] ERROR[32309] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 06:23:45] ERROR[32309] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 06:23:45] ERROR[7602] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 06:23:45] ERROR[2803] pjproject: ssl0x7f0b641d3e60 Renegotiation failed: Not enough memory (PJ_ENOMEM)
      [2017-09-06 06:23:45] VERBOSE[2809] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:38938;transport=TLS is now Unreachable. RTT: 0.000 msec
      [2017-09-06 06:25:44] VERBOSE[7163] res_pjsip_registrar.c: Added contact ‘sips:702@70.44.10.180:45328;transport=TLS’ to AOR ‘702’ with expiration of 3600 seconds
      [2017-09-06 06:25:44] VERBOSE[8236] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:45328;transport=TLS has been created
      [2017-09-06 06:25:44] ERROR[31134] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 06:25:44] ERROR[31134] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 06:25:44] ERROR[31134] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      
      …
      
      [2017-09-06 06:25:44] ERROR[8841] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 06:25:44] ERROR[7163] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 06:25:44] ERROR[2803] pjproject: ssl0x7f0b4c626b10 Renegotiation failed: Not enough memory (PJ_ENOMEM)
      [2017-09-06 06:25:44] VERBOSE[2809] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:45328;transport=TLS is now Unreachable. RTT: 0.000 msec
      [2017-09-06 06:33:36] ERROR[2803] pjproject: sip_endpoint.c Error processing packet from 70.44.10.180:5060: Missing required header(s) (PJSIP_EMISSINGHDR) Via [code 171050]:
      SIP/2.0 400 Bad Request
      From: sip:701@209.222.10.59;tag=bcd2606e-5c15-492c-b6d3-0c934bb00eb4
      To: sip:701@70.44.10.180;tag=9ffa1a1b62bb6a06
      Call-ID: 62929999-00d7-44ed-bb3f-a43ec24ff7a9
      CSeq: 6193 NOTIFY
      User-Agent: Grandstream GXP2020 1.2.5.3
      Warning: 398 "You are not allowed to CANCEL an established dialog"
      Content-Length: 0
      
      – end of packet.
      [2017-09-06 06:34:03] VERBOSE[8236] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:38926;transport=TLS has been deleted
      [2017-09-06 06:34:04] ERROR[2803] pjproject: sip_endpoint.c Error processing packet from 70.44.10.180:5066: Missing required header(s) (PJSIP_EMISSINGHDR) Via [code 171050]:
      SIP/2.0 400 Bad Request
      From: sip:702@209.222.10.59;tag=2c13f4fb-d808-43ef-ba65-b6455e6f978e
      To: sip:702@70.44.10.180;tag=86962d2d9f6b5e8b
      Call-ID: b6f21b3c-85c5-44bc-a7b7-6b8400528244
      CSeq: 4265 NOTIFY
      User-Agent: Grandstream GXP2020 1.2.5.3
      Warning: 398 "You are not allowed to CANCEL an established dialog"
      Content-Length: 0
      
      – end of packet.
      [2017-09-06 06:35:52] VERBOSE[2809] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:45312;transport=TLS has been deleted
      [2017-09-06 06:36:02] VERBOSE[2767] asterisk.c: Remote UNIX connection
      [2017-09-06 06:36:02] VERBOSE[2871] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 06:36:02] VERBOSE[2767] asterisk.c: Remote UNIX connection
      [2017-09-06 06:36:02] VERBOSE[2873] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 06:36:02] VERBOSE[2767] asterisk.c: Remote UNIX connection
      [2017-09-06 06:36:02] VERBOSE[2875] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 06:38:40] VERBOSE[2809] res_pjsip/pjsip_configuration.c: Contact 701/sip:701@70.44.10.180:5060;transport=TCP is now Unreachable. RTT: 0.000 msec
      [2017-09-06 06:41:34] ERROR[2803] pjproject: sip_transport.c Error processing 161 bytes packet from TCP 70.44.10.180:5066 : PJSIP syntax error exception when parsing ‘’ header on line 2 col 7:
      SIP/2.0 400 Bad Request
      CSeq: User-Agent: Grandstream GXP2020 1.2.5.3
      Warning: 398 "You are not allowed to CANCEL an established dialog"
      Content-Length: 0
      
      – end of packet.
      [2017-09-06 06:41:34] ERROR[2803] pjproject: sip_endpoint.c Error processing packet from 70.44.10.180:5066: Missing required header(s) (PJSIP_EMISSINGHDR) Via [code 171050]:
      SIP/2.0 400 Bad Request
      From: sip:702@209.222.10.59;tag=c69e843a-2268-4b15-8253-752439dec7ec
      To: sip:702@70.44.10.180;tag=750369d3-f4fa-406f-a596-7b68de87290e
      Call-ID: cce7be3d-4c88-498f-82dd-bb3b58bac473
      CSeq: 15435 NOTIFY
      User-Agent: Grandstream GXP2020 1.2.5.3
      Warning: 398 "You are not allowed to CANCEL an established dialog"
      Content-Length: 0
      
      – end of packet.
      [2017-09-06 06:41:36] VERBOSE[2809] res_pjsip/pjsip_configuration.c: Contact 702/sip:702@70.44.10.180:5066;transport=TCP has been deleted
      [2017-09-06 07:13:45] VERBOSE[8841] res_pjsip_registrar.c: Added contact ‘sips:702@70.44.10.180:38939;transport=TLS’ to AOR ‘702’ with expiration of 3600 seconds
      [2017-09-06 07:13:45] VERBOSE[2809] res_pjsip/pjsip_configuration.c: Contact 702/sips:702@70.44.10.180:38939;transport=TLS has been created
      [2017-09-06 07:13:45] ERROR[32309] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      [2017-09-06 07:13:45] ERROR[32309] res_pjsip.c: Error 70007 ‘Not enough memory (PJ_ENOMEM)’ sending NOTIFY request to endpoint 702
      

      Thanks leon

      jcolpAsterisk Developer
      2h

      I haven’t seen any issues with such things and I’m aware of a few different major installs. It may be unique to your environment or what you are doing. More information would be useful. How many endpoints, subscriptions, type of transport, etc.
      wa4zlw
      1h

      AM using PJSip for endpoints. THis all worked under Asterisk 13/fpbx 12. very weird
      basically I have three physical extensions 701-703. 703 is not connected now so just two 701 and 702. I have multiple devices talking to those extensions around the house (all grandstream and a zoiper android client which I disabled last night to debug this) On my Watchguard firewall I noticed in my traffic management window I was noticed weird sip behavior with lots of sip traffic. see this display which is no where near as bad as it was last night going over 120kbps!

      image
      image.png738x762 29.5 KB

      Usually the SIP traffic is a flat line with very low bandwidth. It was hoping all around last night.
      Also PJSIP extensions keep dropping out and I have to wait for the timers to expire. Going the debug log from last night you can see errors from the GXP2020 phone up above near the end of my original post.

      On 701 I have PJSIP set for 8 and on 702 I have it set to 6. I usually add an extra 2 count in case things get out of sync

      I have MWI subscriptions set on.

      WOuld you like to get access to the server? If so, please post me privately wa4zlw@arrl.net

      WHat else do you need? I’ve been running top all night and the free memory keeps going down pops up a bit which is what I would expect but something doesnt seem right to me

      THanks leon
      jcolpAsterisk Developer
      1h

      I don’t provide one on one help like that. You’d need to look at the log before errors occur to see if anything looks out of the ordinary, for example is the Asterisk server under attack?
      wa4zlw
      1h

      I also have BLF setup as well for the extensions

      no there is a firewall that freepbx runs so things are locked down.
      the log entries I entered into the ticket is whta I thought unusual and why I added them to the ticket.

      I looked at the previous ticket and it said to open a new one if you were not the original person which is what I did.

      One thing I did do is cut down from 3600 --> 900 seconds the SIP max time

      other than that I’m stumped.

      thanks leon
      wa4zlw
      1h

      here’s another unregistration/disconnection:

      [2017-09-06 11:53:57] VERBOSE[21467] asterisk.c: Remote UNIX connection
      [2017-09-06 11:53:57] VERBOSE[15247] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 11:53:57] VERBOSE[21467] asterisk.c: Remote UNIX connection
      [2017-09-06 11:53:57] VERBOSE[15249] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 11:53:57] VERBOSE[21467] asterisk.c: Remote UNIX connection
      [2017-09-06 11:53:57] VERBOSE[15251] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 12:02:41] VERBOSE[369] res_pjsip/pjsip_configuration.c: Contact 701/sip:701@70.44.10.180:44141;transport=TLS is now Unreachable. RTT: 0.000 msec
      [2017-09-06 12:36:03] VERBOSE[21467] asterisk.c: Remote UNIX connection
      [2017-09-06 12:36:03] VERBOSE[22779] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 12:36:03] VERBOSE[21467] asterisk.c: Remote UNIX connection
      [2017-09-06 12:36:03] VERBOSE[22781] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 12:36:03] VERBOSE[21467] asterisk.c: Remote UNIX connection
      [2017-09-06 12:36:03] VERBOSE[22783] asterisk.c: Remote UNIX connection disconnected
      

      wa4zlw
      1h

      more keep dropping like flies

      [2017-09-06 12:36:03] VERBOSE[21467] asterisk.c: Remote UNIX connection
      [2017-09-06 12:36:03] VERBOSE[22783] asterisk.c: Remote UNIX connection disconnected
      [2017-09-06 12:49:43] VERBOSE[369] res_pjsip/pjsip_configuration.c: Contact 701/sip:701@70.44.10.180:44142;transport=TLS is now Unreachable. RTT: 0.000 msec
      [2017-09-06 12:49:44] VERBOSE[369] res_pjsip/pjsip_configuration.c: Contact 701/sip:701@70.44.10.180:44143;transport=TLS is now Unreachable. RTT: 0.000 msec
      

      jcolpAsterisk Developer
      33m

      That would mean that the TLS connection has dropped, or the endpoint did not respond to our OPTIONS request.
      wa4zlw
      24m

      my latency to the pbx is like 40ms

      and this just happened

      [2017-09-06 12:59:13] VERBOSE[369] res_pjsip/pjsip_configuration.c: Contact 701/sip:701@70.44.10.180:44142;transport=TLS has been deleted
      [2017-09-06 12:59:13] VERBOSE[369] res_pjsip/pjsip_configuration.c: Contact 701/sip:701@70.44.10.180:44141;transport=TLS has been deleted
      [2017-09-06 12:59:13] VERBOSE[369] res_pjsip/pjsip_configuration.c: Contact 701/sip:701@70.44.10.180:44143;transport=TLS has been deleted
      

      this is going on all day up and down…what about the other errors above?

      Thanks leon
      jcolpAsterisk Developer
      22m

      I don’t really have anything to add. You can file an issue[1] with all the information you can. There’s no timeline on when it would get looked into, and as it only seems to be impacting you it could prove difficult to figure out.

      [1] https://issues.asterisk.org/jira

      1. debugoutput10.txt
        5 kB
        Leon Zetekoff
      2. debugoutput3.txt
        71 kB
        Leon Zetekoff
      3. debugoutput4.txt
        5 kB
        Leon Zetekoff
      4. debugoutput5.txt
        84 kB
        Leon Zetekoff
      5. debugoutput5.txt
        34 kB
        Leon Zetekoff
      6. debugoutput6.txt
        46 kB
        Leon Zetekoff
      7. debugoutput7.txt
        33 kB
        Leon Zetekoff
      8. debugoutput9.txt
        2 kB
        Leon Zetekoff
      9. FreePBX.7z
        5.43 MB
        Leon Zetekoff

        Activity

        Hide
        Asterisk Team added a comment -

        This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.

        Show
        Asterisk Team added a comment - This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
        Hide
        Leon Zetekoff added a comment -

        more logs function can only be used on SIP channels
        out of memory

        Show
        Leon Zetekoff added a comment - more logs function can only be used on SIP channels out of memory
        Hide
        Leon Zetekoff added a comment -

        new error related to tls

        Show
        Leon Zetekoff added a comment - new error related to tls
        Hide
        Asterisk Team added a comment -

        This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.

        Show
        Asterisk Team added a comment - This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
        Hide
        Leon Zetekoff added a comment -

        TLS errors

        Show
        Leon Zetekoff added a comment - TLS errors

          People

          • Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development