Problems Retrieving Voicemails

We are having a problem where occasionally voicemail is not being returned for a user. I was able to see it this morning and capture the server log.

For the first request, the client requested the voicemail and the server responded with an empty array for the inbox, two voicemails for the old folder, and empty arrays for the other folders. Every thing was correct except the inbox which should return 26 voicemails.

I then requested the voicemail again and this time the server responded with the correct number of voicemails in each folder.

Can you explain how the fop2 server retrieves the voicemails so we can investigate our system to see if there is something wrong on our end?

Here is the first request:
2016-08-05 05:28:09,553 INFO - 23.240.58.26:64073 <= <msg data="6|getvmail|INBOX|cdd24e08a0c52a2bb18e977f5c1b3df0" />
and the response:
2016-08-05 05:28:09,553 INFO - ++ GET SERVER for USER/4159672901 = 127.0.0.1
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - 127.0.0.1 -> Action: UserEvent
2016-08-05 05:28:09,553 INFO - 127.0.0.1 -> UserEvent: FOP2VMAIL
2016-08-05 05:28:09,553 INFO - 127.0.0.1 -> Channel: USER/4159672901
2016-08-05 05:28:09,553 INFO - 127.0.0.1 -> Mailbox: 4159672901@default
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - 127.0.0.1 <- Response: Success
2016-08-05 05:28:09,553 INFO - 127.0.0.1 <- Message: Event Sent
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - 127.0.0.1 <- Event: UserEvent
2016-08-05 05:28:09,553 INFO - 127.0.0.1 <- Privilege: user,all
2016-08-05 05:28:09,553 INFO - 127.0.0.1 <- UserEvent: FOP2VMAIL
2016-08-05 05:28:09,553 INFO - 127.0.0.1 <- Action: UserEvent
2016-08-05 05:28:09,553 INFO - 127.0.0.1 <- Channel: USER/4159672901
2016-08-05 05:28:09,553 INFO - 127.0.0.1 <- Mailbox: 4159672901@default
2016-08-05 05:28:09,553 INFO - Executing AMI Event Handler in plugin hcpeerstatus for event USEREVENT
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - Checking ODBC voicemail connection
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - Checking ODBC voicemail connection
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - Checking ODBC voicemail connection
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - Checking ODBC voicemail connection
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - Checking ODBC voicemail connection
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - ** CALLING QUERY UNPOPULATED MAILBOX on FOP2::AMI2=HASH(0x11289ea8)
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data INBOX!eyJJTkJPWCI6IFt7fV19, slot 0
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,553 INFO - END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data Old!eyJPbGQiOiBbeyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjAiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjkxIiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvT2xkIiwiY2FsbGVyaWQiOiAiXCI0OTczODhcIiA8NDk3Mzg4PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDUyODkwNjUyICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2MzQ5In0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjEiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjk2IiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvT2xkIiwiY2FsbGVyaWQiOiAiXCJUZXN0XCIgPDQ0NDQ0ND4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ2NjQ1MDE5OCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM3MiJ9XX0=, slot 0
2016-08-05 05:28:09,553 INFO -
2016-08-05 05:28:09,602 INFO - END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data Work!eyJXb3JrIjogW3t9XX0=, slot 0
2016-08-05 05:28:09,602 INFO -
2016-08-05 05:28:09,602 INFO - END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data Family!eyJGYW1pbHkiOiBbe31dfQ==, slot 0
2016-08-05 05:28:09,602 INFO -
2016-08-05 05:28:09,602 INFO - END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data Friends!eyJGcmllbmRzIjogW3t9XX0=, slot 0

and here is the second request and response:

2016-08-05 05:38:06,723 INFO - 23.240.58.26:64073 <= <msg data="6|getvmail|INBOX|cdd24e08a0c52a2bb18e977f5c1b3df0" />
2016-08-05 05:38:06,723 INFO -
2016-08-05 05:38:06,723 INFO - -- PROCESS_FLASH_COMMAND origen 6 accion getvmail destino INBOX password cdd24e08a0c52a2bb18e977f5c1b3df0
2016-08-05 05:38:06,723 INFO -
2016-08-05 05:38:06,723 INFO - ++ GET SERVER for USER/4159672901 = 127.0.0.1
2016-08-05 05:38:06,723 INFO -
2016-08-05 05:38:06,723 INFO - 127.0.0.1 -> Action: UserEvent
2016-08-05 05:38:06,723 INFO - 127.0.0.1 -> UserEvent: FOP2VMAIL
2016-08-05 05:38:06,723 INFO - 127.0.0.1 -> Channel: USER/4159672901
2016-08-05 05:38:06,723 INFO - 127.0.0.1 -> Mailbox: 4159672901@default
2016-08-05 05:38:06,723 INFO -
2016-08-05 05:38:06,723 INFO - 127.0.0.1 <- Response: Success
2016-08-05 05:38:06,723 INFO - 127.0.0.1 <- Message: Event Sent
2016-08-05 05:38:06,723 INFO -
2016-08-05 05:38:06,723 INFO - 127.0.0.1 <- Event: UserEvent
2016-08-05 05:38:06,723 INFO - 127.0.0.1 <- Privilege: user,all
2016-08-05 05:38:06,723 INFO - 127.0.0.1 <- UserEvent: FOP2VMAIL
2016-08-05 05:38:07,407 INFO - 127.0.0.1 <- Action: UserEvent
2016-08-05 05:38:07,407 INFO - 127.0.0.1 <- Channel: USER/4159672901
2016-08-05 05:38:07,407 INFO - 127.0.0.1 <- Mailbox: 4159672901@default
2016-08-05 05:38:07,407 INFO -
2016-08-05 05:38:07,407 INFO - Executing AMI Event Handler in plugin hcpeerstatus for event USEREVENT
2016-08-05 05:38:07,407 INFO -
2016-08-05 05:38:07,407 INFO - Checking ODBC voicemail connection
2016-08-05 05:38:07,407 INFO -
2016-08-05 05:38:07,407 INFO - Checking ODBC voicemail connection
2016-08-05 05:38:07,407 INFO -
2016-08-05 05:38:07,407 INFO - Checking ODBC voicemail connection
2016-08-05 05:38:07,407 INFO -
2016-08-05 05:38:07,407 INFO - Checking ODBC voicemail connection
2016-08-05 05:38:07,407 INFO -
2016-08-05 05:38:07,407 INFO - Checking ODBC voicemail connection
2016-08-05 05:38:07,407 INFO -
2016-08-05 05:38:07,407 INFO - ** CALLING QUERY UNPOPULATED MAILBOX on FOP2::AMI2=HASH(0x11289ea8)


2016-08-05 05:38:07,407 INFO -
2016-08-05 05:38:07,407 INFO - END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data INBOX!eyJJTkJPWCI6IFt7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiMTIiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjExIiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvSU5CT1giLCJjYWxsZXJpZCI6ICJcIkNPTExJTkcgV0lMTElBTVwiIDwrMTk1MTk0MTQ4NzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0Njk5MDMwMzYgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjYzODgifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiMTMiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjExIiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvSU5CT1giLCJjYWxsZXJpZCI6ICJcIkNPTExJTkcgV0lMTElBTVwiIDwrMTk1MTk0MTQ4NzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0Njk5MDMwNzEgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjYzODkifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiMTQiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjExIiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvSU5CT1giLCJjYWxsZXJpZCI6ICJcIkNPTExJTkcgV0lMTElBTVwiIDwrMTk1MTk0MTQ4NzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0Njk5MDMxMDcgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjYzOTAifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiMCIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiMTEiLCJtYWNyb2NvbnRleHQiOiAiZXh0LWxvY2FsIiwiZGlyIjogIi92YXIvc3Bvb2wvYXN0ZXJpc2svdm9pY2VtYWlsL2RlZmF1bHQvNDE1OTY3MjkwMS9JTkJPWCIsImNhbGxlcmlkIjogIlwiQ09MTElORyxXSUxMSUFNXCIgPDk1MTc4MDc3MzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0Njk4MDIxMzggICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjYzNzYifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiMSIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiOCIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HLFdJTExJQU1cIiA8OTUxNzgwNzczNj4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ2OTgwMjE5MCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM3NyJ9LHsibWFpbGJveHVzZXIiOiAiNDE1OTY3MjkwMSIsIm1zZ251bSI6ICIyIiwiZmxhZyI6ICIiLCJkdXJhdGlvbiI6ICI5IiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvSU5CT1giLCJjYWxsZXJpZCI6ICJcIkNPTExJTkcsV0lMTElBTVwiIDw5NTE3ODA3NzM2PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDY5ODAzMjg2ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2Mzc4In0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjMiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjEwIiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvSU5CT1giLCJjYWxsZXJpZCI6ICJcIkNPTExJTkcsV0lMTElBTVwiIDw5NTE3ODA3NzM2PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDY5ODAzMzE3ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2Mzc5In0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjQiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjgiLCJtYWNyb2NvbnRleHQiOiAiZXh0LWxvY2FsIiwiZGlyIjogIi92YXIvc3Bvb2wvYXN0ZXJpc2svdm9pY2VtYWlsL2RlZmF1bHQvNDE1OTY3MjkwMS9JTkJPWCIsImNhbGxlcmlkIjogIlwiQ09MTElORyxXSUxMSUFNXCIgPDk1MTc4MDc3MzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0Njk4MDMzNDggICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjYzODAifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiNSIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiOSIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HLFdJTExJQU1cIiA8OTUxNzgwNzczNj4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ2OTgwMzM3OSAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM4MSJ9LHsibWFpbGJveHVzZXIiOiAiNDE1OTY3MjkwMSIsIm1zZ251bSI6ICI2IiwiZmxhZyI6ICIiLCJkdXJhdGlvbiI6ICIxMyIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HLFdJTExJQU1cIiA8OTUxNzgwNzczNj4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ2OTgwMzQwOCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM4MiJ9LHsibWFpbGJveHVzZXIiOiAiNDE1OTY3MjkwMSIsIm1zZ251bSI6ICI3IiwiZmxhZyI6ICIiLCJkdXJhdGlvbiI6ICI4IiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvSU5CT1giLCJjYWxsZXJpZCI6ICJcIkNPTExJTkcsV0lMTElBTVwiIDw5NTE3ODA3NzM2PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDY5ODAzNDQxICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2MzgzIn0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjgiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjkiLCJtYWNyb2NvbnRleHQiOiAiZXh0LWxvY2FsIiwiZGlyIjogIi92YXIvc3Bvb2wvYXN0ZXJpc2svdm9pY2VtYWlsL2RlZmF1bHQvNDE1OTY3MjkwMS9JTkJPWCIsImNhbGxlcmlkIjogIlwiQ09MTElORyxXSUxMSUFNXCIgPDk1MTc4MDc3MzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0Njk4MDM0NzAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjYzODQifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiOSIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiMTEiLCJtYWNyb2NvbnRleHQiOiAiZXh0LWxvY2FsIiwiZGlyIjogIi92YXIvc3Bvb2wvYXN0ZXJpc2svdm9pY2VtYWlsL2RlZmF1bHQvNDE1OTY3MjkwMS9JTkJPWCIsImNhbGxlcmlkIjogIlwiQ09MTElORyxXSUxMSUFNXCIgPDk1MTc4MDc3MzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0Njk4MDM0OTggICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjYzODUifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiMTAiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjE3IiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvSU5CT1giLCJjYWxsZXJpZCI6ICJcIkNPTExJTkcsV0lMTElBTVwiIDw5NTE3ODA3NzM2PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDY5ODAzNTM1ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2Mzg2In0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjExIiwiZmxhZyI6ICIiLCJkdXJhdGlvbiI6ICIxNCIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HIFdJTExJQU1cIiA8KzE5NTE5NDE0ODc2PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDY5OTAyOTg4ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2Mzg3In0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjE1IiwiZmxhZyI6ICIiLCJkdXJhdGlvbiI6ICIxMyIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HIFdJTExJQU1cIiA8KzE5NTE5NDE0ODc2PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDY5OTAzMTQ1ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2MzkxIn0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjE2IiwiZmxhZyI6ICIiLCJkdXJhdGlvbiI6ICIxNCIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HIFdJTExJQU1cIiA8KzE5NTE5NDE0ODc2PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDY5OTAzMTgzICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2MzkyIn0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjE3IiwiZmxhZyI6ICIiLCJkdXJhdGlvbiI6ICIxMiIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HIFdJTExJQU1cIiA8KzE5NTE5NDE0ODc2PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDY5OTAzMjU5ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2MzkzIn0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjE4IiwiZmxhZyI6ICIiLCJkdXJhdGlvbiI6ICIxMSIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HLFdJTExJQU1cIiA8OTUxNzgwNzczNj4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ3MDA1NzM3MSAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM5NCJ9LHsibWFpbGJveHVzZXIiOiAiNDE1OTY3MjkwMSIsIm1zZ251bSI6ICIxOSIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiNyIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HLFdJTExJQU1cIiA8OTUxNzgwNzczNj4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ3MDA1NzQwMyAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM5NSJ9LHsibWFpbGJveHVzZXIiOiAiNDE1OTY3MjkwMSIsIm1zZ251bSI6ICIyMCIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiNiIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HLFdJTExJQU1cIiA8OTUxNzgwNzczNj4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ3MDA1NzQzMCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM5NiJ9LHsibWFpbGJveHVzZXIiOiAiNDE1OTY3MjkwMSIsIm1zZ251bSI6ICIyMSIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiNiIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HLFdJTExJQU1cIiA8OTUxNzgwNzczNj4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ3MDA1NzQ1OCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM5NyJ9LHsibWFpbGJveHVzZXIiOiAiNDE1OTY3MjkwMSIsIm1zZ251bSI6ICIyMiIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiOSIsIm1hY3JvY29udGV4dCI6ICJleHQtbG9jYWwiLCJkaXIiOiAiL3Zhci9zcG9vbC9hc3Rlcmlzay92b2ljZW1haWwvZGVmYXVsdC80MTU5NjcyOTAxL0lOQk9YIiwiY2FsbGVyaWQiOiAiXCJDT0xMSU5HLFdJTExJQU1cIiA8OTUxNzgwNzczNj4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ3MDA1NzQ4NCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM5OCJ9LHsibWFpbGJveHVzZXIiOiAiNDE1OTY3MjkwMSIsIm1zZ251bSI6ICIyMyIsImZsYWciOiAiIiwiZHVyYXRpb24iOiAiMTAiLCJtYWNyb2NvbnRleHQiOiAiZXh0LWxvY2FsIiwiZGlyIjogIi92YXIvc3Bvb2wvYXN0ZXJpc2svdm9pY2VtYWlsL2RlZmF1bHQvNDE1OTY3MjkwMS9JTkJPWCIsImNhbGxlcmlkIjogIlwiQ09MTElORyxXSUxMSUFNXCIgPDk1MTc4MDc3MzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0NzAwNTc1MTMgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjYzOTkifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiMjQiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjUiLCJtYWNyb2NvbnRleHQiOiAiZXh0LWxvY2FsIiwiZGlyIjogIi92YXIvc3Bvb2wvYXN0ZXJpc2svdm9pY2VtYWlsL2RlZmF1bHQvNDE1OTY3MjkwMS9JTkJPWCIsImNhbGxlcmlkIjogIlwiQ09MTElORyxXSUxMSUFNXCIgPDk1MTc4MDc3MzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0NzAwNTc1NDYgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjY0MDAifSx7Im1haWxib3h1c2VyIjogIjQxNTk2NzI5MDEiLCJtc2dudW0iOiAiMjUiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjkiLCJtYWNyb2NvbnRleHQiOiAiZXh0LWxvY2FsIiwiZGlyIjogIi92YXIvc3Bvb2wvYXN0ZXJpc2svdm9pY2VtYWlsL2RlZmF1bHQvNDE1OTY3MjkwMS9JTkJPWCIsImNhbGxlcmlkIjogIlwiQ09MTElORyxXSUxMSUFNXCIgPDk1MTc4MDc3MzY+IiwibWFpbGJveGNvbnRleHQiOiAiZGVmYXVsdCIsIm9yaWd0aW1lIjogIjE0NzAwNTc1NzEgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIiwiY29udGV4dCI6ICJtYWNyby12bSIsImlkIjogIjY0MDEifV19, slot 0
2016-08-05 05:38:07,408 INFO -
2016-08-05 05:38:07,408 INFO - END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data Old!eyJPbGQiOiBbeyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjAiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjkxIiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvT2xkIiwiY2FsbGVyaWQiOiAiXCI0OTczODhcIiA8NDk3Mzg4PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDUyODkwNjUyICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2MzQ5In0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjEiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjk2IiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvT2xkIiwiY2FsbGVyaWQiOiAiXCJUZXN0XCIgPDQ0NDQ0ND4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ2NjQ1MDE5OCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM3MiJ9XX0=, slot 0
2016-08-05 05:38:07,408 INFO -
2016-08-05 05:38:07,408 INFO - END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data Work!eyJXb3JrIjogW3t9XX0=, slot 0
2016-08-05 05:38:07,782 INFO -
2016-08-05 05:38:07,782 INFO - 23.240.58.26:64073 => { "btn": "6@GENERAL", "cmd": "vmaildetail", "data": "Family!eyJGYW1pbHkiOiBbe31dfQ==", "slot": "0" }
2016-08-05 05:38:07,782 INFO -
2016-08-05 05:38:07,782 INFO - 23.240.58.26:64073 => { "btn": "6@GENERAL", "cmd": "vmaildetail", "data": "Friends!eyJGcmllbmRzIjogW3t9XX0=", "slot": "0" }

Comments

  • Hi,
    In your case I believe you are using odbc, voicemails are retrieved using odbc and performing queries to retrieve them. You can inspect mysql by having it log queries and see what is the query being used to retrieve voicemails each time.



  • Thanks for the information. I can now reproduce the problem by the following:

    1. Log into the FOP2 interface.
    2. Bounce mysql (service mysqld restart)
    3. Request voicemail by clicking on the envelope icon on the extension button.

    I turned on the general log for mysql to see if I could see the problem. Here is what I saw:

    In the normal case where all voicemails are returned, the fop2 server issues a query for each voicemail folder and for each msgnum returned another query is issued for the voicemail details.

    Example:

    Query for INBOX msgnum:
    SELECT `msgnum` FROM `voicemail`.`voicemessages` WHERE ((`dir` LIKE BINARY '%INBOX')) AND ((`mailboxuser` = '4159672901')) AND ((`mailboxcontext` = 'default'))

    Query for each msgnum in INBOX:
    SELECT `id`, `msgnum`, `dir`, `context`, `macrocontext`, `callerid`, `origtime`, `duration`, `mailboxuser`, `mailboxcontext`, `flag` FROM `voicemail`.`voicemessages` WHERE ((`dir` LIKE BINARY '%INBOX')) AND ((`mailboxuser` = '4159672901')) AND ((`mailboxcontext` = 'default')) AND ((`msgnum` = 12))

    The query for msgnum is done for the INBOX, Old, Work, Family, and Friends folders.

    After I restart mysqld, for the first voicemail request only, the fop2 server only queries for the Old, Work, Family, and Friends folders. For some reason, it does not query for INBOX. This then explains why the INBOX voicemails are missing in the response.

    I am not clear how the fop2 server knows which voicemail folders should be returned. Can you give us a little information on what happens here?
  • Hi Nicolas,

    Could it just be that the ODBC session is stale and the FOP server isn't doing a retry?

    If I run a similar test with 2 different browsers (B1 and B2) connected with the same user and then:

    bounce mysqld.
    open the VM dialog with B1 I see the same failure being reported by wcolling.
    But if I then immediately open the same VM dialog in B2 after B1 failing, B2 displays the New folder ok

    Can you confirm that error handling behavior if when you try and connect to an ODBC resource and you receive some sort of exception?

    Thanks,

    JPS
  • Hi Jamuel,

    You can start the FOP2 server with full debug mode. If there is an ODBC hiccup, it will be logged. FOP2 attempts a reconnection if it notices a problem, and it logs about it also.

    You can grep for the string "voicemail connection" on the full log when debug level includes bit 128 (so you could run with -X 128 to get *only* those messages and some other few).

    Best regards,
  • We ran the test. For the first query we see:

    Checking ODBC voicemail connection

    Checking ODBC voicemail connection

    Checking ODBC voicemail connection

    Checking ODBC voicemail connection

    Checking ODBC voicemail connection

    END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data INBOX!eyJJTkJ...
    The full contents of INBOX are returned.

    I then bounced mysqld and requested the voicemail.

    Checking ODBC voicemail connection

    DBD::ODBC::st execute failed: [unixODBC]Error while executing the query;
    ERROR: failed to execute the MySQL query:
    MySQL server has gone away (SQL-HV00L) at /tmp/par-root/cache-18b38fcffafe18b85ee9f07de91069f7509b888c/inc/lib/FOP2/voicemail.pm line 31.
    Describe failed during DBI::st=HASH(0x10342248)->FETCH(NAME,0) at /tmp/par-root/cache-18b38fcffafe18b85ee9f07de91069f7509b888c/inc/lib/FOP2/voicemail.pm line 33.
    Checking ODBC voicemail connection

    Checking ODBC voicemail connection

    Checking ODBC voicemail connection

    Checking ODBC voicemail connection

    END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data INBOX!eyJJTkJPWCI6IFt7fV19, slot 0

    END HANDLING AMI EVENT channel USER/4159672901, command vmaildetail, data Old!eyJPbGQiOiBbeyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjAiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjkxIiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvT2xkIiwiY2FsbGVyaWQiOiAiXCI0OTczODhcIiA8NDk3Mzg4PiIsIm1haWxib3hjb250ZXh0IjogImRlZmF1bHQiLCJvcmlndGltZSI6ICIxNDUyODkwNjUyICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICIsImNvbnRleHQiOiAibWFjcm8tdm0iLCJpZCI6ICI2MzQ5In0seyJtYWlsYm94dXNlciI6ICI0MTU5NjcyOTAxIiwibXNnbnVtIjogIjEiLCJmbGFnIjogIiIsImR1cmF0aW9uIjogIjk2IiwibWFjcm9jb250ZXh0IjogImV4dC1sb2NhbCIsImRpciI6ICIvdmFyL3Nwb29sL2FzdGVyaXNrL3ZvaWNlbWFpbC9kZWZhdWx0LzQxNTk2NzI5MDEvT2xkIiwiY2FsbGVyaWQiOiAiXCJUZXN0XCIgPDQ0NDQ0ND4iLCJtYWlsYm94Y29udGV4dCI6ICJkZWZhdWx0Iiwib3JpZ3RpbWUiOiAiMTQ2NjQ1MDE5OCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAiLCJjb250ZXh0IjogIm1hY3JvLXZtIiwiaWQiOiAiNjM3MiJ9XX0=, slot 0

    Here an empty array was returned for INBOX.

    If I understand this correctly, the query for inbox is issued and there is a problem with the connection, the FOP2 server recovers the connection, fails to reattempt the read for INBOX and continues on with the Old folder.

  • You are probably correct. I will have to recreate such a setup and brake connections on purpose to work on it. I will see if I can do something about it in the next few weeks. Best regards,
Sign In or Register to comment.