Hi all
Anyone out there had issues with their plugin blocking until startup is complete. I am having a play with AMI in Asterisk and not having much luck moving from the startup part of the plugin.
I request authentication but the response does not come back until after startup even using intercept.
Any info appreciated.
Have not made any progress on this except that the to find that with or without intercept none of the incoming data appears until after the startup function returns.
More info
AMI packets are made up of lines terminated with CRLF
End of AMI packet terminates with CRLF CRLF
I have used “raw” protocol as “crlf” protocol does not give me any indication of an empty packet (just a packet consisting of CRLF)
log file for startup
10 05/07/13 21:47:55.602 XXX-UpdateSystemMessagesTasks now 1=Asterisk[64]: Starting Lua Engine timeout 0 (-1367934475) count: 3pend:Starting Lua Engine/err:(null)/done:(null) <0x803>
10 05/07/13 21:47:55.602 UserData::m_iDataVersion_Variables_incr short sys message user data 934453001 variables 934453073 <0x803>
31 05/07/13 21:47:55.603 AlarmManager::Run finish callback for alarm 0x790348 entry 0x8a26f8 type 24 id 41 param=(nil) entry->when: 1367934475 time: 1367934475 tnum: 1 slow 0 duration 0 <0x803>
10 05/07/13 21:47:55.604 AlarmManager::AddAbsoluteAlarm alarm 0x790348 entry 0x7fe610 id 42 type 24 param=(nil) entry->when: 1367934475 time: 1367934475 bCancelFirst 0=0 <0x402>
25 05/07/13 21:47:55.605 LuImplementation::StartLua running startup code for 64 I_Asterisk1.xml <0x402>
06 05/07/13 21:47:55.606 Device_Variable::m_szValue_set device: 64 service: urn:zoot-com:serviceId:AMIAsterisk1 variable: AMIVersion was: 1.2 now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x402>
10 05/07/13 21:47:55.606 UserData::m_iDataVersion_Variables_incr AMIVersion user data 934453001 variables 934453074 <0x402>
10 05/07/13 21:47:55.607 UserData::DataIsDirty UpdateStateList was 1 incr 0 user data 934453001 variables 934453074 <0x402>
10 05/07/13 21:47:55.608 UserData::m_iDataVersion_Variables_incr startup user data 934453001 variables 934453075 <0x402>
10 05/07/13 21:47:55.609 AlarmManager::AddRelativeAlarm current time 1367934475 delay 0 type 24 <0x402>
10 05/07/13 21:47:55.610 AlarmManager::AddAbsoluteAlarm alarm 0x790348 entry 0x7cda68 id 43 type 24 param=(nil) entry->when: 1367934475 time: 1367934475 bCancelFirst 0=0 <0x402>
01 05/07/13 21:47:55.611 luup_log:64: AsteriskAMI: Debug: AMIClientStart: ipAddress=192.168.0.32, ipPort=5038 <0x402>
10 05/07/13 21:47:55.612 Device_LuaUPnP::StartIOPort device 64 64 192.168.0.32:5038 (nil) <0x402>
32 05/07/13 21:47:55.613 ThreadedClass::StartThread class 0x8a4c78 started 0x580c <0x402>
25 05/07/13 21:47:55.614 IOPort::ConfirmSocketHandle device 64 waiting up to 30 seconds for connection <0x402>
31 05/07/13 21:47:55.615 AlarmManager::Run 0x790348 notified of a change entry 0x889a08 id 36 deleted 0 <0x803>
31 05/07/13 21:47:55.615 AlarmManager::Run callback for alarm 0x790348 entry 0x7fe610 type 24 id 42 param=(nil) entry->when: 1367934475 time: 1367934475 tnum: 1 slow 0 tardy 0 <0x803>
110 05/07/13 21:47:55.617 XXX-UpdateSystemMessagesTasks now 1=AMI Plugin: startup timeout 0 (-1367934475) count: 3pend:startup/err:(null)/done:(null) <0x803>
10 05/07/13 21:47:55.618 UserData::m_iDataVersion_Variables_incr short sys message user data 934453001 variables 934453076 <0x803>
31 05/07/13 21:47:55.619 AlarmManager::Run finish callback for alarm 0x790348 entry 0x7fe610 type 24 id 42 param=(nil) entry->when: 1367934475 time: 1367934475 tnum: 1 slow 0 duration 0 <0x803>
31 05/07/13 21:47:55.620 AlarmManager::Run callback for alarm 0x790348 entry 0x7cda68 type 24 id 43 param=(nil) entry->when: 1367934475 time: 1367934475 tnum: 1 slow 0 tardy 0 <0x803>
10 05/07/13 21:47:55.622 XXX-UpdateSystemMessagesTasks now 1=AMI Plugin: startup timeout 0 (-1367934475) count: 3pend:startup/err:(null)/done:(null) <0x803>
10 05/07/13 21:47:55.623 UserData::m_iDataVersion_Variables_incr short sys message user data 934453001 variables 934453077 <0x803>
31 05/07/13 21:47:55.623 AlarmManager::Run finish callback for alarm 0x790348 entry 0x7cda68 type 24 id 43 param=(nil) entry->when: 1367934475 time: 1367934475 tnum: 1 slow 0 duration 0 <0x803>
35 05/07/13 21:47:55.624 PIDLOG 10495 start ThreadedClassThread <0x580c>
32 05/07/13 21:47:55.625 ThreadedClassThread::ThreadedClassThread running internal run ptr 0x8a4c78 <0x580c>
32 05/07/13 21:47:55.625 ThreadedClass::InternalRun <0x580c>
35 05/07/13 21:47:55.626 IOPort::Run starting for 64 <0x580c>
25 05/07/13 21:47:55.627 IOPort::Connect device 64 connecting to 192.168.0.32:5038 iodevice: 0 path (null) <0x580c>
25 05/07/13 21:47:55.628 IOPort::Connect connect 1: 192.168.0.32:5038 <0x580c>
25 05/07/13 21:47:55.630 IOPort::Connect connect 3: 192.168.0.32:5038 m_socket_handle 14 <0x580c>
25 05/07/13 21:47:55.631 IOPort::Connect OK 192.168.0.32:5038 <0x580c>
52 05/07/13 21:47:55.632 0x41 (A) <0x580c>
25 05/07/13 21:47:55.710 IOPort::ConfirmSocketHandle device 64 success 1 handle 14 connecting 0 <0x402>
01 05/07/13 21:47:55.711 luup_log:64: AsteriskAMI: Debug: AMI request login. <0x402>Connection works OK, a connection message should come in that says: -
Asterisk Call Manager/1.2All I get back is: -
52 05/07/13 21:47:55.632 0x41 (A) <0x580c>until startup function is complete then any data queued from commands or events cascades in.
10 05/07/13 21:48:05.018 XXX-UpdateSystemMessagesTasks now 1=AMI Plugin: startup timeout 0 (-1367934485) count: 3pend:startup/err:(null)/done:(null) <0x803>
10 05/07/13 21:48:05.019 UserData::m_iDataVersion_Variables_incr short sys message user data 934453001 variables 934453104 <0x803>
31 05/07/13 21:48:05.020 AlarmManager::Run finish callback for alarm 0x790348 entry 0x7fe610 type 24 id 47 param=(nil) entry->when: 1367934485 time: 1367934485 tnum: 1 slow 0 duration 0 <0x803>
25 05/07/13 21:48:05.730 IOPort::GetIncomingData after wait 0x7f7ff248 data (nil) <0x402>
25 05/07/13 21:48:05.731 lu_io_read result 0 bytes 0 <0x402>
01 05/07/13 21:48:05.732 luup_log:64: AsteriskAMI: Debug: _______________________________________________________________No data <0x402>
11 05/07/13 21:48:05.733 Child_Devices::Synchronize 0 devices parent 64 <0x402>
11 05/07/13 21:48:05.733 Child_Devices::Synchronize parent: 64 0 new and 0 removed devices <0x402>
01 05/07/13 21:48:05.734 luup_log:64: AsteriskAMI: Debug: Startup complete <0x402>
50 05/07/13 21:48:05.735 luup_log:64: AsteriskAMI: task: startup complete <0x402>
10 05/07/13 21:48:05.736 UserData::m_iDataVersion_Variables_incr startup user data 934453001 variables 934453105 <0x402>
10 05/07/13 21:48:05.736 AlarmManager::AddRelativeAlarm current time 1367934485 delay 0 type 24 <0x402>
10 05/07/13 21:48:05.737 AlarmManager::AddAbsoluteAlarm alarm 0x790348 entry 0x858520 id 48 type 24 param=(nil) entry->when: 1367934485 time: 1367934485 bCancelFirst 0=0 <0x402>
31 05/07/13 21:48:05.738 AlarmManager::Run 0x790348 notified of a change entry 0x889a08 id 36 deleted 0 <0x803>
31 05/07/13 21:48:05.739 AlarmManager::Run callback for alarm 0x790348 entry 0x858520 type 24 id 48 param=(nil) entry->when: 1367934485 time: 1367934485 tnum: 1 slow 0 tardy 0 <0x803>
10 05/07/13 21:48:05.741 XXX-UpdateSystemMessagesTasks StartupTask #2 = 4 startup complete / AMI Plugin <0x803>
10 05/07/13 21:48:05.742 XXX-UpdateSystemMessagesTasks now -1=(null) timeout 0 (-1367934485) count: 3pend:(null)/err:(null)/done:(null) <0x803>
10 05/07/13 21:48:05.743 UserData::m_iDataVersion_Variables_incr short sys message user data 934453001 variables 934453106 <0x803>
31 05/07/13 21:48:05.743 AlarmManager::Run finish callback for alarm 0x790348 entry 0x858520 type 24 id 48 param=(nil) entry->when: 1367934485 time: 1367934485 tnum: 1 slow 0 duration 0 <0x803>
20 05/07/13 21:48:06.230 LuaInterface::CallFunction_Startup-1 0x886ef0 mutex_unlock 0x8a4ca8 <0x402>
10 05/07/13 21:48:06.231 UserData::m_iDataVersion_Variables_incr startup user data 934453001 variables 934453107 <0x402>
10 05/07/13 21:48:06.232 AlarmManager::AddRelativeAlarm current time 1367934486 delay 0 type 24 <0x402>
10 05/07/13 21:48:06.232 AlarmManager::AddAbsoluteAlarm alarm 0x790348 entry 0x858520 id 49 type 24 param=(nil) entry->when: 1367934486 time: 1367934486 bCancelFirst 0=0 <0x402>
31 05/07/13 21:48:06.233 AlarmManager::Run finish callback for alarm 0x790348 entry 0x8b5df0 type 5 id 15 param=0x81a2e8 entry->when: 1367934463 time: 1367934486 tnum: 0 slow 1 duration 11 <0x402>
31 05/07/13 21:48:06.234 AlarmManager::Run callback for alarm 0x790348 entry 0x8587c8 type 25 id 28 param=(nil) entry->when: 1367934464 time: 1367934486 tnum: 0 slow 1 tardy 22 <0x402>
52 05/07/13 21:48:06.278 0x73 (s) <0x580c>
52 05/07/13 21:48:06.280 0x74 (t) <0x580c>
52 05/07/13 21:48:06.281 0x65 (e) <0x580c>
52 05/07/13 21:48:06.283 0x72 (r) <0x580c>
52 05/07/13 21:48:06.284 0x69 (i) <0x580c>
52 05/07/13 21:48:06.285 0x73 (s) <0x580c>
52 05/07/13 21:48:06.287 0x6b (k) <0x580c>
52 05/07/13 21:48:06.288 0x20 ( ) <0x580c>
52 05/07/13 21:48:06.289 0x43 (C) <0x580c>
52 05/07/13 21:48:06.290 0x61 (a) <0x580c>
52 05/07/13 21:48:06.292 0x6c (l) <0x580c>
52 05/07/13 21:48:06.293 0x6c (l) <0x580c>
52 05/07/13 21:48:06.294 0x20 ( ) <0x580c>
52 05/07/13 21:48:06.296 0x4d (M) <0x580c>
52 05/07/13 21:48:06.297 0x61 (a) <0x580c>
52 05/07/13 21:48:06.298 0x6e (n) <0x580c>
52 05/07/13 21:48:06.300 0x61 (a) <0x580c>
52 05/07/13 21:48:06.302 0x67 (g) <0x580c>
52 05/07/13 21:48:06.303 0x65 (e) <0x580c>
52 05/07/13 21:48:06.304 0x72 (r) <0x580c>
52 05/07/13 21:48:06.306 0x2f (/) <0x580c>
52 05/07/13 21:48:06.307 0x31 (1) <0x580c>
52 05/07/13 21:48:06.308 0x2e (.) <0x580c>
52 05/07/13 21:48:06.309 0x32 (2) <0x580c>
It looks like a bug to me that only shows itself in certain circumstances but would like to get opinions before raising request. The reality is that I will probably give up on this plugin as I have not been able to find a way around this and probably not a lot of interest outside by own desires 
Thanks
Zoot