jigasi
jigasi copied to clipboard
jitsi
Jigasi gives up on reaching the SIP server after several minutes
Description
We are using Jigasi with Asterisk (via udp on 127.0.0.1) to allow SIP-based Dialins for our Jitsi Conferences. This works fine as long as Asterisk is already running. If Asterisk is not reachable for some minutes Jigasi wont try to REGISTER anymore and has to be restarted.
Current behavior
Jun 18 15:46:12 meet-sipgw conmon[2405674]: 2024-06-18 13:46:12.317 INFO: [323] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: Setting SIPMessage peerPacketSource to: /127.0.0.1:5060
Jun 18 15:46:12 meet-sipgw podman[2405647]: 2024-06-18 13:46:12.317 INFO: [323] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: Setting SIPMessage peerPacketSource to: /127.0.0.1:5060
# asterisk stopped...
Jun 18 15:52:22 meet-sipgw conmon[2405674]: 2024-06-18 13:52:22.880 INFO: [34] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Registered; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.]
Jun 18 15:52:22 meet-sipgw podman[2405647]: 2024-06-18 13:52:22.880 INFO: [34] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Registered; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.]
Jun 18 15:52:22 meet-sipgw conmon[2405674]: 2024-06-18 13:52:22.891 INFO: [34] net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper.scheduleReconnectIfNeeded: Reconnect ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) after 5000 ms.
Jun 18 15:52:22 meet-sipgw podman[2405647]: 2024-06-18 13:52:22.891 INFO: [34] net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper.scheduleReconnectIfNeeded: Reconnect ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) after 5000 ms.
Jun 18 15:52:22 meet-sipgw conmon[2405674]: 2024-06-18 13:52:22.903 INFO: [34] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 18 15:52:22 meet-sipgw podman[2405647]: 2024-06-18 13:52:22.903 INFO: [34] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 18 15:52:23 meet-sipgw conmon[2405674]: 2024-06-18 13:52:23.905 INFO: [34] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 18 15:52:23 meet-sipgw podman[2405647]: 2024-06-18 13:52:23.905 INFO: [34] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 18 15:52:27 meet-sipgw conmon[2405674]: 2024-06-18 13:52:27.901 INFO: [37] net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper$ReconnectTask.run: Start reconnecting ProtocolProviderServiceSipImpl(SIP:jigasi@localhost)
Jun 18 15:52:27 meet-sipgw podman[2405647]: 2024-06-18 13:52:27.901 INFO: [37] net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper$ReconnectTask.run: Start reconnecting ProtocolProviderServiceSipImpl(SIP:jigasi@localhost)
Jun 18 15:52:27 meet-sipgw conmon[2405674]: 2024-06-18 13:52:27.910 INFO: [37] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been started
Jun 18 15:52:27 meet-sipgw podman[2405647]: 2024-06-18 13:52:27.910 INFO: [37] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been started
Jun 18 15:52:27 meet-sipgw conmon[2405674]: 2024-06-18 13:52:27.925 INFO: [37] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Unregistered; newState=RegistrationState=Registering; userRequest=false; reasonCode=-1; reason=null]
Jun 18 15:52:27 meet-sipgw podman[2405647]: 2024-06-18 13:52:27.925 INFO: [37] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Unregistered; newState=RegistrationState=Registering; userRequest=false; reasonCode=-1; reason=null]
Jun 18 15:53:33 meet-sipgw conmon[2405674]: 2024-06-18 13:53:33.901 INFO: [325] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Registering; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.]
Jun 18 15:53:33 meet-sipgw podman[2405647]: 2024-06-18 13:53:33.901 INFO: [325] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Registering; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.]
Jun 18 15:53:33 meet-sipgw conmon[2405674]: 2024-06-18 13:53:33.911 INFO: [325] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 18 15:53:33 meet-sipgw podman[2405647]: 2024-06-18 13:53:33.911 INFO: [325] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 18 15:53:34 meet-sipgw conmon[2405674]: 2024-06-18 13:53:34.912 INFO: [325] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 18 15:53:34 meet-sipgw podman[2405647]: 2024-06-18 13:53:34.912 INFO: [325] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
# starting asterisk again
Expected Behavior
It would be desirable to have Jigasi try to re-establish the SIP Registration and not giving up finally.
Possible Solution
Maybe it is possible to configure the SIP-Timers behaviour to not time out?!
Steps to reproduce
- register Jigasi to a SIP-Server
- shut down the SIP-Server
- wait ~ 5 Minutes
- restart SIP-Server
- watch Jigasi not register anymore
Environment details
We are using Jigasi1.1.329-g04ad08fLinux respectively Container Image: jitsi/jigasi:stable-9457-2 with Asterisk 18.10.0~dfsg+~cs6.10.40431411-2 (should not matter).
According to the logs after starting asterisk jigasi tried registering but timed out:
Jun 18 15:52:27 meet-sipgw podman[2405647]: 2024-06-18 13:52:27.925 INFO: [37] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Unregistered; newState=RegistrationState=Registering; userRequest=false; reasonCode=-1; reason=null]
# starting asterisk again
Jun 18 15:53:33 meet-sipgw conmon[2405674]: 2024-06-18 13:53:33.901 INFO: [325] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Registering; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.]
Hi @damencho, yeah thats correct. The thing is, this also happens if Jigasi is running fine for weeks and the upstream system then goes unavail for some minutes (due to maintenance from another team)..
I have an idea about SIP-Timers and that this behaviour may be correct regarding RFCs, but from a production point of view the SIP-Bridge to Jitsi just breaks forever (until restarted) if the upstream SIP-Service is maintained for some minutes.
A Setting/Flag to have Jigasi recovery automatically would be very helpful in this case.
I don't understand the problem i terms of jigasi. After the service is back jigasi retries again and is not succeeding, not sure how to recover from this.
We are handling this by checking the health of jigasi, when it becomes an healthy a new i stance is scaled up and the old one goes into graceful shutdown.
I don't understand the problem i terms of jigasi. After the service is back jigasi retries again and is not succeeding, not sure how to recover from this.
Yeah, that would be my expectation in this case too :)
Example:
- Asterisk and Jigasi are running and Jigasi is registered and handling incoming calls fine
- stopped Asterisk at 08:27:12
- Jigasi tries to Re-Register and is sending OPTIONS until 08:37:45
- Jigasi logs this:
Jun 19 08:37:46 meet-sipgw conmon[2438867]: 2024-06-19 06:37:46.082 INFO: [53] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Registering; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.]
Jun 19 08:37:46 meet-sipgw podman[2438839]: 2024-06-19 06:37:46.082 INFO: [53] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Registering; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.]
Jun 19 08:37:46 meet-sipgw conmon[2438867]: 2024-06-19 06:37:46.093 INFO: [53] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 19 08:37:46 meet-sipgw podman[2438839]: 2024-06-19 06:37:46.093 INFO: [53] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 19 08:37:47 meet-sipgw conmon[2438867]: 2024-06-19 06:37:47.095 INFO: [53] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 19 08:37:47 meet-sipgw podman[2438839]: 2024-06-19 06:37:47.095 INFO: [53] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
- Jigasi stops sending anything via SIP
- Asterisk is started again
- Jigasi has to be restarted
08:37:45.580762 IP6 localhost.5062 > localhost.sip: SIP: REGISTER sip:localhost SIP/2.0
..............`......@.......................................
REGISTER sip:localhost SIP/2.0
Call-ID: bad395fd3f176bff6e79e5496716ebac@0:0:0:0:0:0:0:0
CSeq: 2 REGISTER
From: "jigasi" <sip:jigasi@localhost>;tag=4d358235
To: "jigasi" <sip:jigasi@localhost>
Via: SIP/2.0/UDP [0:0:0:0:0:0:0:1]:5062;branch=z9hG4bK-383639-0680c5ef6718283f71eff44605274e2b
Max-Forwards: 70
User-Agent: Jigasi1.1.329-g04ad08fLinux
Expires: 600
Contact: "jigasi" <sip:jigasi@[0:0:0:0:0:0:0:1]:5062;transport=udp;registering_acc=localhost>;expires=600
Content-Length: 0
# 08:51:30
We are handling this by checking the health of jigasi, when it becomes an healthy a new i stance is scaled up and the old one goes into graceful shutdown.
Is there a way to check Jigasis Health via http like for the JVBS, or is this only possible via XMPP? :)
Do you have any idea, if it is possible to configure Jigasi respecitvely the SIP-Timer Settings in a way that Jigasi does not stop trying to Re-Register? From my point of view it would make sense to be able to configure this behaviour..
And thanks for the hint regarding the http health check, after testing and looking in the source i think i missed configuring the sipChecker to get a good status :)
Do you have any idea, if it is possible to configure Jigasi respecitvely the SIP-Timer Settings in a way that Jigasi does not stop trying to Re-Register? From my point of view it would make sense to be able to configure this behaviour..
Not sure what you are talking about. There is a reconnect plugin that controls the reconnecting logic for protocol providers and there is no logic of stopping reconnect, if I remember correctly. You can enable debug logging and when you see it stops create a heapdump to try debugging why it may have stopped reconnecting. We haven't seen that in practice, but if there is an incident with the sip provider it is short or we spin up new instances.
https://github.com/jitsi/jitsi/tree/master/modules/plugin/reconnect
Thanks for the pointer!
To me it looks as the reconnect plugin doesnt do anything when the problem occurs:
❯ grep -i -e reconnect -e '13:14:0' /tmp/jigasi_stops_registering.log
Jun 19 13:12:53 meet-sipgw podman[2489842]: 2024-06-19 11:12:53.811 INFO: [34] net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper.scheduleReconnectIfNeeded: Reconnect ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) after 4000 ms.
Jun 19 13:12:53 meet-sipgw podman[2489842]: 2024-06-19 11:12:53.833 FINEST: [34] net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper.registrationStateChanged: Got Connection Failed for ProtocolProviderServiceSipImpl(SIP:jigasi@localhost)
Jun 19 13:12:53 meet-sipgw podman[2489842]: at net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper.registrationStateChanged(PPReconnectWrapper.java:225)
Jun 19 13:12:53 meet-sipgw podman[2489842]: 2024-06-19 11:12:53.838 FINEST: [34] net.java.sip.communicator.plugin.reconnectplugin.ReconnectPluginActivator.traceCurrentPPState: connectedInterfaces: [cni-podman0, eth0]
Jun 19 13:12:53 meet-sipgw podman[2489842]: 2024-06-19 11:12:53.884 FINEST: [34] net.java.sip.communicator.plugin.reconnectplugin.ReconnectPluginActivator.traceCurrentPPState: reconnectEnabledProviders: [PPReconnectWrapper[provider=ProtocolProviderServiceSipImpl(SIP:jigasi@localhost), currentlyUnregistering=false, currentReconnect=ReconnectTask [delay=4000, provider=ProtocolProviderServiceSipImpl(SIP:jigasi@localhost)], reconnectOnNextUnregisteredDelay=null]]
Jun 19 13:12:53 meet-sipgw podman[2489842]: 2024-06-19 11:12:53.889 FINEST: [34] net.java.sip.communicator.plugin.reconnectplugin.ReconnectPluginActivator.traceCurrentPPState: ----
Jun 19 13:12:57 meet-sipgw podman[2489842]: 2024-06-19 11:12:57.834 INFO: [37] net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper$ReconnectTask.run: Start reconnecting ProtocolProviderServiceSipImpl(SIP:jigasi@localhost)
Jun 19 13:12:57 meet-sipgw podman[2489842]: at net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper$ReconnectTask.run(PPReconnectWrapper.java:452)
Jun 19 13:12:57 meet-sipgw podman[2489842]: at net.java.sip.communicator.plugin.reconnectplugin.PPReconnectWrapper$ReconnectTask.run(PPReconnectWrapper.java:452)
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.461 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: sendMessage 0:0:0:0:0:0:0:1/5060
Jun 19 13:14:01 meet-sipgw podman[2489842]: messageSize = 495 message = REGISTER sip:localhost SIP/2.0
Jun 19 13:14:01 meet-sipgw podman[2489842]: Call-ID: 23da9347dbf59e4669e47ceb5bc6b1da@0:0:0:0:0:0:0:0
Jun 19 13:14:01 meet-sipgw podman[2489842]: CSeq: 2 REGISTER
Jun 19 13:14:01 meet-sipgw podman[2489842]: From: "jigasi" <sip:jigasi@localhost>;tag=992566b4
Jun 19 13:14:01 meet-sipgw podman[2489842]: To: "jigasi" <sip:jigasi@localhost>
Jun 19 13:14:01 meet-sipgw podman[2489842]: Via: SIP/2.0/UDP [0:0:0:0:0:0:0:1]:5062;branch=z9hG4bK-343631-8ebb2108d134e11b5ae68df8ac453374
Jun 19 13:14:01 meet-sipgw podman[2489842]: Max-Forwards: 70
Jun 19 13:14:01 meet-sipgw podman[2489842]: User-Agent: Jigasi1.1.329-g04ad08fLinux
Jun 19 13:14:01 meet-sipgw podman[2489842]: Expires: 600
Jun 19 13:14:01 meet-sipgw podman[2489842]: Contact: "jigasi" <sip:jigasi@[0:0:0:0:0:0:0:1]:5062;transport=udp;registering_acc=localhost>;expires=600
Jun 19 13:14:01 meet-sipgw podman[2489842]: Content-Length: 0
Jun 19 13:14:01 meet-sipgw podman[2489842]:
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.468 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: *******************
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.961 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: fireTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransactionImpl@2a6462f7
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.963 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: sipDialogs = [] default dialog null retval null
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.965 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: handleEvent javax.sip.TimeoutEvent[source=gov.nist.javax.sip.SipProviderImpl@702dc8a]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransactionImpl@2a6462f7this.sipListener = net.java.sip.communicator.impl.protocol.sip.SipStackSharing@3d73b7a0sipEvent.source = gov.nist.javax.sip.SipProviderImpl@702dc8a
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.967 FINEST: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace: JAIN-SIP stack trace
Jun 19 13:14:01 meet-sipgw podman[2489842]: java.lang.Throwable
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace(SipLogger.java:71)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.core.CommonLogger.logStackTrace(CommonLogger.java:111)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:175)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipProviderImpl.transactionErrorEvent(SipProviderImpl.java:968)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.raiseErrorEvent(SIPTransactionImpl.java:960)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl.fireTimeoutTimer(SIPClientTransactionImpl.java:1177)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.fireTimer(SIPTransactionImpl.java:661)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl$TransactionTimer.runTask(SIPClientTransactionImpl.java:259)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.run(Timer.java:516)
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.972 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: sipEvent = javax.sip.TimeoutEvent[source=gov.nist.javax.sip.SipProviderImpl@702dc8a]source = gov.nist.javax.sip.SipProviderImpl@702dc8a
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.973 FINEST: [158] net.java.sip.communicator.impl.protocol.sip.SipStackSharing.getServiceData: service was found in request data
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.977 FINE: [158] net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.processTimeout: received timeout for req=REGISTER sip:localhost SIP/2.0
Jun 19 13:14:01 meet-sipgw podman[2489842]: Call-ID: 23da9347dbf59e4669e47ceb5bc6b1da@0:0:0:0:0:0:0:0
Jun 19 13:14:01 meet-sipgw podman[2489842]: CSeq: 2 REGISTER
Jun 19 13:14:01 meet-sipgw podman[2489842]: From: "jigasi" <sip:jigasi@localhost>;tag=992566b4
Jun 19 13:14:01 meet-sipgw podman[2489842]: To: "jigasi" <sip:jigasi@localhost>
Jun 19 13:14:01 meet-sipgw podman[2489842]: Via: SIP/2.0/UDP [0:0:0:0:0:0:0:1]:5062;branch=z9hG4bK-343631-8ebb2108d134e11b5ae68df8ac453374
Jun 19 13:14:01 meet-sipgw podman[2489842]: Max-Forwards: 70
Jun 19 13:14:01 meet-sipgw podman[2489842]: User-Agent: Jigasi1.1.329-g04ad08fLinux
Jun 19 13:14:01 meet-sipgw podman[2489842]: Expires: 600
Jun 19 13:14:01 meet-sipgw podman[2489842]: Contact: "jigasi" <sip:jigasi@[0:0:0:0:0:0:0:1]:5062;transport=udp;registering_acc=localhost>;expires=600
Jun 19 13:14:01 meet-sipgw podman[2489842]: Content-Length: 0
Jun 19 13:14:01 meet-sipgw podman[2489842]:
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.977 FINE: [158] net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.processTimeout: Found 1 processor(s) for method REGISTER
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.977 FINE: [158] net.java.sip.communicator.impl.protocol.sip.net.ManualProxyConnection.getNextAddressFromDns: No more addresses for SIP:jigasi@localhost
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.978 FINE: [158] net.java.sip.communicator.service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged: Dispatching RegistrationStateChangeEvent[ oldState=Registering; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.] to 11 listeners.
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.979 FINE: [158] net.java.sip.communicator.impl.protocol.sip.OperationSetPresenceSipImpl.registrationStateChanged: Enter connction failed state
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.983 FINE: [158] net.java.sip.communicator.service.protocol.AbstractOperationSetPersistentPresence.fireProviderStatusChangeEvent: Dispatching Provider Status Change. Listeners=0 evt=ProviderPresenceStatusChangeEvent-[OldStatus=PresenceStatus:Offline, NewStatus=PresenceStatus:Offline]
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.983 FINE: [158] net.java.sip.communicator.service.protocol.AbstractOperationSetPersistentPresence.fireProviderStatusChangeEvent: status dispatching done.
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.983 FINE: [158] net.java.sip.communicator.impl.protocol.sip.OperationSetBasicInstantMessagingSipImpl$RegistrationStateListener.registrationStateChanged: The provider changed state from: RegistrationState=Registering to: RegistrationState=Connection Failed
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.984 FINE: [158] net.java.sip.communicator.impl.protocol.sip.OperationSetTypingNotificationsSipImpl$RegistrationStateListener.registrationStateChanged: The provider changed state from: RegistrationState=Registering to: RegistrationState=Connection Failed
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.987 INFO: [158] SipGateway.registrationStateChanged#120: REG STATE CHANGE ProtocolProviderServiceSipImpl(SIP:jigasi@localhost) -> RegistrationStateChangeEvent[ oldState=Registering; newState=RegistrationState=Connection Failed; userRequest=false; reasonCode=-1; reason=A timeout occurred while trying to connect to the server.]
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.987 FINEST: [158] net.java.sip.communicator.impl.protocol.sip.SipStackSharing.removeSipListener: 0 listeners left
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.989 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: Exiting provider
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.990 FINE: [160] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: UDPMessageProcessor: Stopping
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.992 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: Exiting provider
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.993 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: Closing 0 sockets from IOHandler
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.994 FINEST: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace: JAIN-SIP stack trace
Jun 19 13:14:01 meet-sipgw podman[2489842]: java.lang.Throwable
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace(SipLogger.java:82)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.core.CommonLogger.logStackTrace(CommonLogger.java:116)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.timers.DefaultSipTimer.stop(DefaultSipTimer.java:137)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionStack.stopStack(SIPTransactionStack.java:2122)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipStackImpl.deleteSipProvider(SipStackImpl.java:1665)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.stopListening(SipStackSharing.java:467)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.removeSipListener(SipStackSharing.java:223)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.registrationStateChanged(ProtocolProviderServiceSipImpl.java:2627)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged(AbstractProtocolProviderService.java:185)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.setRegistrationState(SipRegistrarConnection.java:737)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.setRegistrationState(SipRegistrarConnection.java:713)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.processTimeout(SipRegistrarConnection.java:1112)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.processTimeout(ProtocolProviderServiceSipImpl.java:908)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.processTimeout(SipStackSharing.java:836)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.EventScanner.deliverTimeoutEvent(EventScanner.java:401)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:150)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:185)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipProviderImpl.transactionErrorEvent(SipProviderImpl.java:968)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.raiseErrorEvent(SIPTransactionImpl.java:960)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl.fireTimeoutTimer(SIPClientTransactionImpl.java:1177)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.fireTimer(SIPTransactionImpl.java:661)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl$TransactionTimer.runTask(SIPClientTransactionImpl.java:259)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
Jun 19 13:14:01 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.run(Timer.java:516)
Jun 19 13:14:01 meet-sipgw podman[2489842]: 2024-06-19 11:14:01.996 INFO: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 19 13:14:03 meet-sipgw podman[2489842]: 2024-06-19 11:14:02.997 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: stopStack -- stoppping the stack
Jun 19 13:14:03 meet-sipgw podman[2489842]: 2024-06-19 11:14:02.997 FINEST: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace: JAIN-SIP stack trace
Jun 19 13:14:03 meet-sipgw podman[2489842]: java.lang.Throwable
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace(SipLogger.java:71)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.core.CommonLogger.logStackTrace(CommonLogger.java:111)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipStackImpl.stop(SipStackImpl.java:1749)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.stopListening(SipStackSharing.java:484)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.removeSipListener(SipStackSharing.java:223)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.registrationStateChanged(ProtocolProviderServiceSipImpl.java:2627)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged(AbstractProtocolProviderService.java:185)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.setRegistrationState(SipRegistrarConnection.java:737)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.setRegistrationState(SipRegistrarConnection.java:713)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.processTimeout(SipRegistrarConnection.java:1112)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.processTimeout(ProtocolProviderServiceSipImpl.java:908)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.processTimeout(SipStackSharing.java:836)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.EventScanner.deliverTimeoutEvent(EventScanner.java:401)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:150)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:185)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipProviderImpl.transactionErrorEvent(SipProviderImpl.java:968)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.raiseErrorEvent(SIPTransactionImpl.java:960)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl.fireTimeoutTimer(SIPClientTransactionImpl.java:1177)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.fireTimer(SIPTransactionImpl.java:661)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl$TransactionTimer.runTask(SIPClientTransactionImpl.java:259)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.run(Timer.java:516)
Jun 19 13:14:03 meet-sipgw podman[2489842]: 2024-06-19 11:14:02.997 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: Closing 0 sockets from IOHandler
Jun 19 13:14:03 meet-sipgw podman[2489842]: 2024-06-19 11:14:02.997 FINEST: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace: JAIN-SIP stack trace
Jun 19 13:14:03 meet-sipgw podman[2489842]: java.lang.Throwable
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace(SipLogger.java:82)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.core.CommonLogger.logStackTrace(CommonLogger.java:116)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.timers.DefaultSipTimer.stop(DefaultSipTimer.java:137)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionStack.stopStack(SIPTransactionStack.java:2122)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipStackImpl.stop(SipStackImpl.java:1751)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.stopListening(SipStackSharing.java:484)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.removeSipListener(SipStackSharing.java:223)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.registrationStateChanged(ProtocolProviderServiceSipImpl.java:2627)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged(AbstractProtocolProviderService.java:185)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.setRegistrationState(SipRegistrarConnection.java:737)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.setRegistrationState(SipRegistrarConnection.java:713)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipRegistrarConnection.processTimeout(SipRegistrarConnection.java:1112)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.ProtocolProviderServiceSipImpl.processTimeout(ProtocolProviderServiceSipImpl.java:908)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.processTimeout(SipStackSharing.java:836)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.EventScanner.deliverTimeoutEvent(EventScanner.java:401)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:150)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:185)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.SipProviderImpl.transactionErrorEvent(SipProviderImpl.java:968)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.raiseErrorEvent(SIPTransactionImpl.java:960)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl.fireTimeoutTimer(SIPClientTransactionImpl.java:1177)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.fireTimer(SIPTransactionImpl.java:661)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl$TransactionTimer.runTask(SIPClientTransactionImpl.java:259)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.run(Timer.java:516)
Jun 19 13:14:03 meet-sipgw podman[2489842]: 2024-06-19 11:14:03.009 INFO: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logInfo: Info from the JAIN-SIP stack: the sip stack timer gov.nist.javax.sip.stack.timers.DefaultSipTimer has been stopped
Jun 19 13:14:03 meet-sipgw podman[2489842]: 2024-06-19 11:14:03.855 SEVERE: [164] SipHealthPeriodicChecker.doRunInternal#252: Health check failed in 7ms:
Jun 19 13:14:03 meet-sipgw podman[2489842]: net.java.sip.communicator.service.protocol.OperationFailedException: The protocol provider should be registered before placing an outgoing call.
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.assertRegistered(OperationSetBasicTelephonySipImpl.java:2180)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.createOutgoingCall(OperationSetBasicTelephonySipImpl.java:156)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.createOutgoingCall(OperationSetBasicTelephonySipImpl.java:191)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.createCall(OperationSetBasicTelephonySipImpl.java:139)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at org.jitsi.jigasi.health.SipHealthPeriodicChecker.doCheck(SipHealthPeriodicChecker.java:328)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at org.jitsi.jigasi.health.SipHealthPeriodicChecker.doRunInternal(SipHealthPeriodicChecker.java:233)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at org.jitsi.jigasi.health.SipHealthPeriodicChecker$1.run(SipHealthPeriodicChecker.java:262)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
Jun 19 13:14:03 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.run(Timer.java:516)
Jun 19 13:14:04 meet-sipgw podman[2489842]: 2024-06-19 11:14:04.010 FINEST: [158] net.java.sip.communicator.impl.protocol.sip.SipStackSharing.stopListening: stopped listening
Jun 19 13:14:04 meet-sipgw podman[2489842]: 2024-06-19 11:14:04.010 FINEST: [158] net.java.sip.communicator.service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged: Done.
Jun 19 13:14:04 meet-sipgw podman[2489842]: 2024-06-19 11:14:04.010 FINE: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logDebug: Debug output from the JAIN-SIP stack: Transaction:setState 5 gov.nist.javax.sip.stack.SIPClientTransactionImpl@2a6462f7 branchID = z9hG4bK-343631-8ebb2108d134e11b5ae68df8ac453374 isClient = true
Jun 19 13:14:04 meet-sipgw podman[2489842]: 2024-06-19 11:14:04.011 FINEST: [158] net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace: JAIN-SIP stack trace
Jun 19 13:14:04 meet-sipgw podman[2489842]: java.lang.Throwable
Jun 19 13:14:04 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.SipLogger.logStackTrace(SipLogger.java:71)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at gov.nist.core.CommonLogger.logStackTrace(CommonLogger.java:111)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.setState(SIPTransactionImpl.java:564)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl.setState(SIPClientTransactionImpl.java:1414)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.raiseErrorEvent(SIPTransactionImpl.java:970)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl.fireTimeoutTimer(SIPClientTransactionImpl.java:1177)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPTransactionImpl.fireTimer(SIPTransactionImpl.java:661)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.SIPClientTransactionImpl$TransactionTimer.runTask(SIPClientTransactionImpl.java:259)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
Jun 19 13:14:04 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.run(Timer.java:516)
...
The REGISTER from 13:14:01 is the last try of sending SIP Messages and after several messages like
Debug output from the JAIN-SIP stack: stopStack -- stoppping the stack
there is no more SIP from Jigasi..
But anyhow, thanks again for the hint regarding the health endpoint! I think i can configure podman to use that as an active healthcheck and have the container restarted automatically in case of failures :)
You see your provider is in reconnectEnabledProviders, so if connection fails it should be detected by the reconnect plugin and continue attempts later.
Right now (14:40) the only (repeating) log messages are:
Jun 19 14:35:53 meet-sipgw podman[2489842]: 2024-06-19 12:35:53.653 SEVERE: [248] SipHealthPeriodicChecker.doRunInternal#252: Health check failed in 1ms:
Jun 19 14:35:53 meet-sipgw podman[2489842]: net.java.sip.communicator.service.protocol.OperationFailedException: The protocol provider should be registered before placing an outgoing call.
Jun 19 14:35:53 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.assertRegistered(OperationSetBasicTelephonySipImpl.java:2180)
Jun 19 14:35:53 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.createOutgoingCall(OperationSetBasicTelephonySipImpl.java:156)
Jun 19 14:35:53 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.createOutgoingCall(OperationSetBasicTelephonySipImpl.java:191)
Jun 19 14:35:53 meet-sipgw podman[2489842]: at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.createCall(OperationSetBasicTelephonySipImpl.java:139)
Jun 19 14:35:53 meet-sipgw podman[2489842]: at org.jitsi.jigasi.health.SipHealthPeriodicChecker.doCheck(SipHealthPeriodicChecker.java:328)
Jun 19 14:35:53 meet-sipgw podman[2489842]: at org.jitsi.jigasi.health.SipHealthPeriodicChecker.doRunInternal(SipHealthPeriodicChecker.java:233)
Jun 19 14:35:53 meet-sipgw podman[2489842]: at org.jitsi.jigasi.health.SipHealthPeriodicChecker$1.run(SipHealthPeriodicChecker.java:262)
Jun 19 14:35:53 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
Jun 19 14:35:53 meet-sipgw podman[2489842]: at java.base/java.util.TimerThread.run(Timer.java:516)
I still have tcpdump running and the last SIP Message is from 13:14:01 - as you can see in the logs from my last post..
Is there any special switch/configparameter neccessary to have the reconnectplugin to do its magic? :) As i mentioned, i am using the Jigasi docker image.. maybe the config is missing something?
Nope, it should be running always. Maybe there is some bug or something. A heapdump will be helpful, but I'm not sure I will have time to look at it these days.
I generated a heapdump with jmap -dump:format=b,file=heap.bin $pid - i am not sure if it helpful if i attach 40MB here.. is there anythin i can provide from the heapdump to provide helpful information?
Do not attach it, as it holds the jigasi memory and configuration. Well, it needs somone to check what is going on in the logs. And see in memory whether ReconnectPluginActivator has the sip provider in reconnectEnabledProviders and if it is there, why there is no scheduled task for it - the internal state for its PPReconnectWrapper. https://github.com/jitsi/jitsi/blob/master/modules/plugin/reconnect/src/main/java/net/java/sip/communicator/plugin/reconnectplugin/PPReconnectWrapper.java