App responds with "480 Temporarily unavailable" once call is accepted

[sanchi]

Sometimes the App goes into a funny state where an incoming call is shown (Accept + Reject buttons), the App responds normally with a "180 Ringing" message, but once the Accept button is pressed, the App returns a "480 Temporarily Unavailable" to the server.

Here's a log file from the server; it clearly shows that the 480 comes from the App.

kamailio_log_2017-11-17-19_12_04.txt

Maybe it's possible to get a log via adb logcat from such a behaviour?

[rodrigomonelos]

Can this be explored without much effort @gmarcos87 so we understand what it takes to fix it?

[sanchi]

I am seeing this also with the send-sms version 4df84ff

[sanchi]

and i still can't figure out why the app is sending 480 as I can't get the log from my Chrome mobile... @gmarcos87 can you reproduce this?

[gmarcos87]

I can not reproduce, but what is your situation? Installed application or web? https or http address?
It only happened to me entering through http (that does not give permission of microphone or camera).

[sanchi]

installed app on chrome/mobile. https address

[gmarcos87]

Ok, can you debug the application on Android and send me the logs?
https://developers.google.com/web/tools/chrome-devtools/remote-debugging/

[sanchi]

finally got my hands on a USB-debuggable device... To me it looks as if when the Chrome remote-debugging is enabled, the app stays always open (connected), so it works (clicking on the notification only pushes the app to the foreground and accepts the call, that works).

I caught one instance of 480 with adb logcat - but it doesn't make any sense to me. It says 'status changed to CONFIRMED' and then sends 480:

12-14 16:32:32.791  2763  2763 I Telecom : MdmExtension: phoneRestrictionPolicy: android.app.enterprise.PhoneRestrictionPolicy@64e27cf
12-14 16:32:32.801  2763  2763 D EnterpriseDeviceManagerService: isManagedProfileUser(): userId = 0
12-14 16:32:32.801  2763  2763 E PhoneRestrictionPolicy: getEmergencyCall >>false
12-14 16:32:32.801  2763  2763 I Telecom : MdmExtension: isEmergencyCallOnly : false
12-14 16:32:32.811  3297  3297 D ResourcesManager: For user 0 new overlays fetched Null
12-14 16:32:32.821  2763  2763 D CustomFrequencyManagerService: releaseDVFSLockLocked : Getting Lock type frm List : DVFS_MIN_LIMIT  frequency : 1500000  uid : 1000  pid : 2763  tag : ACTIVITY_RESUME_BOOSTER@9
12-14 16:32:33.241  2763  4007 D BatteryService: !@BatteryListener : batteryPropertiesChanged!
12-14 16:32:33.241  2763  4007 D BatteryService: level:78, scale:100, status:2, health:2, present:true, voltage: 4074, temperature: 263, technology: Li-ion, AC powered:false, USB powered:true, POGO powered:false, Wireless powered:false, icon:17303412, invalid charger:0, maxChargingCurrent:0
12-14 16:32:33.241  2763  4007 D BatteryService: online:4, current avg:0, charge type:1, power sharing:false, high voltage charger:false, capacity:280000, batterySWSelfDischarging:false, current_now:0
12-14 16:32:33.241  2763  2763 D BatteryService: Sending ACTION_BATTERY_CHANGED.
12-14 16:32:33.241  2763  2763 I MotionRecognitionService: Plugged
12-14 16:32:33.241  2763  2763 D MotionRecognitionService:   cableConnection= 1
12-14 16:32:33.241  2763  2763 D MotionRecognitionService: setPowerConnected | current backoff  = 1024 , state =1024
12-14 16:32:33.241  2763  2763 D MotionRecognitionService: skip setTransmitPower. 
12-14 16:32:33.251  3190  3190 D KeyguardUpdateMonitor: received broadcast android.intent.action.BATTERY_CHANGED
12-14 16:32:33.251  3190  3190 D PowerUI : priorPlugType = 2 mPlugType =  2
12-14 16:32:33.251  3190  3190 D KeyguardUpdateMonitor: handleBatteryUpdate
12-14 16:32:33.251  3190  3190 D PowerUI.Notification: Charging remaining time is not supported and connected cable is not a fast/slow charger, so return!
12-14 16:32:33.251  3190  3190 D BatteryMeterView: ACTION_BATTERY_CHANGED : level:78 status:2 health:2
12-14 16:32:33.271  3190  3190 D BatteryMeterView: ACTION_BATTERY_CHANGED : level:78 status:2 health:2
12-14 16:32:33.681 18760 18760 I chromium: [INFO:CONSOLE(1)] "%cJsSIP:RTCSession %canswer()%c +10s", source: https://pearlcel.webph.one/main.d61fce2299f69f15b634.bundle.js (1)
12-14 16:32:33.681 18760 18760 I chromium: [INFO:CONSOLE(1)] "%cJsSIP:Dialog %cdialog htjfg14q3m5bpatlac9cb738aej5ckv9ms6c1mo2  changed to CONFIRMED state%c +10s", source: https://pearlcel.webph.one/main.d61fce2299f69f15b634.bundle.js (1)
12-14 16:32:33.721 21184 21231 W chromium: [WARNING:delay_based_bwe.cc(361)] BWE Setting start bitrate to: 300000
12-14 16:32:33.781 18760 18760 I chromium: [INFO:CONSOLE(1)] "%cJsSIP:Transport %csend()%c +10s", source: https://pearlcel.webph.one/main.d61fce2299f69f15b634.bundle.js (1)
12-14 16:32:33.781 18760 18760 I chromium: [INFO:CONSOLE(1)] "%cJsSIP:Transport %csending message:
12-14 16:32:33.781 18760 18760 I chromium: 
12-14 16:32:33.781 18760 18760 I chromium: SIP/2.0 480 Temporarily Unavailable
12-14 16:32:33.781 18760 18760 I chromium: Via: SIP/2.0/WSS 138.68.99.252:8443;branch=z9hG4bK54d.d9ce66141c70715b80d24b49e0860d7a.0
12-14 16:32:33.781 18760 18760 I chromium: Via: SIP/2.0/WSS ejsdghci66b5.invalid;rport=42773;received=77.179.15.204;branch=z9hG4bK6452679
12-14 16:32:33.781 18760 18760 I chromium: To: <sip:99910016925@rhizortc.specialstories.org>;tag=b738aej5ck
12-14 16:32:33.781 18760 18760 I chromium: From: "99910010636" <sip:99910010636@rhizortc.specialstories.org>;tag=v9ms6c1mo2
12-14 16:32:33.781 18760 18760 I chromium: Call-ID: htjfg14q3m5bpatlac9c
12-14 16:32:33.781 18760 18760 I chromium: CSeq: 8148 INVITE
12-14 16:32:33.781 18760 18760 I chromium: Supported: timer,ice,replaces,outbound
12-14 16:32:33.781 18760 18760 I chromium: Content-Length: 0
12-14 16:32:33.781 18760 18760 I chromium: 
12-14 16:32:33.781 18760 18760 I chromium: 
12-14 16:32:33.781 18760 18760 I chromium: %c +0ms", source: https://pearlcel.webph.one/main.d61fce2299f69f15b634.bundle.js (1)
12-14 16:32:33.781 18760 18760 I chromium: [INFO:CONSOLE(1)] "%cJsSIP:WebSocketInterface %csend()%c +10s", source: https://